From 1d43944bea00c2808fb746ba6a3bc84625807cb2 Mon Sep 17 00:00:00 2001 From: Timothy Pansino <11214426+TimPansino@users.noreply.github.com> Date: Thu, 17 Nov 2022 12:04:32 -0800 Subject: [PATCH 1/9] Log Forwarding User Attributes (#682) * Add context data setting Co-authored-by: Uma Annamalai Co-authored-by: Hannah Stepanek Co-authored-by: Lalleh Rafeei * 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 Co-authored-by: Hannah Stepanek Co-authored-by: Lalleh Rafeei Co-authored-by: Hannah Stepanek --- newrelic/api/application.py | 4 +- newrelic/api/log.py | 27 ++- newrelic/api/transaction.py | 18 +- newrelic/common/encoding_utils.py | 23 ++ newrelic/config.py | 1 + newrelic/core/agent.py | 4 +- newrelic/core/application.py | 4 +- newrelic/core/config.py | 9 + newrelic/core/stats_engine.py | 12 +- newrelic/hooks/logger_logging.py | 18 +- newrelic/hooks/logger_loguru.py | 4 +- tests/agent_features/test_log_events.py | 198 +++++++++++------- tests/agent_features/test_logs_in_context.py | 16 +- .../test_attribute_forwarding.py | 54 +++++ tests/logger_logging/test_logging_handler.py | 28 ++- tests/logger_loguru/conftest.py | 5 + .../test_attribute_forwarding.py | 54 +++++ .../validators/validate_log_event_count.py | 2 +- ...ate_log_event_count_outside_transaction.py | 2 +- .../validators/validate_log_events.py | 17 +- ...validate_log_events_outside_transaction.py | 18 +- 21 files changed, 396 insertions(+), 122 deletions(-) create mode 100644 tests/logger_logging/test_attribute_forwarding.py create mode 100644 tests/logger_loguru/test_attribute_forwarding.py diff --git a/newrelic/api/application.py b/newrelic/api/application.py index e2e7be139..9297509bc 100644 --- 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 index 846ef275a..2c372117b 100644 --- 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 "" % 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 index bbe8f3852..d0164eaf2 100644 --- 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 index bee53df1a..e89573324 100644 --- 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 "" % type(obj).__name__ + + # Functions for obfuscating/deobfuscating text string based on an XOR # cipher. diff --git a/newrelic/config.py b/newrelic/config.py index d08d51dff..b1bff73a8 100644 --- 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 index 9d9aadab1..376f90c9f 100644 --- 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 index 82cdf8a9a..dcdb21f64 100644 --- 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 index 9bb0ca774..aba1db10b 100644 --- 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 index ebebe7dbe..c39ec5e6e 100644 --- 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 index 67fb46525..27fd7edc6 100644 --- a/newrelic/hooks/logger_logging.py +++ b/newrelic/hooks/logger_logging.py @@ -12,11 +12,14 @@ # 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 @@ -24,6 +27,9 @@ 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 index dc9843b20..57427625c 100644 --- 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 diff --git a/tests/agent_features/test_log_events.py b/tests/agent_features/test_log_events.py index bb173d6c4..b62d6a5fc 100644 --- a/tests/agent_features/test_log_events.py +++ b/tests/agent_features/test_log_events.py @@ -17,11 +17,33 @@ from newrelic.api.transaction import current_transaction, record_log_event, ignore_transaction 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 validate_log_event_count_outside_transaction +from testing_support.validators.validate_log_event_count_outside_transaction import ( + validate_log_event_count_outside_transaction, +) from testing_support.validators.validate_log_events import validate_log_events from testing_support.validators.validate_log_events_outside_transaction import validate_log_events_outside_transaction +class NonPrintableObject(object): + def __str__(self): + raise RuntimeError("Unable to print object.") + + __repr__ = __str__ + + +class NonSerializableObject(object): + def __str__(self): + return "<%s object>" % self.__class__.__name__ + + __repr__ = __str__ + + +def combine_dicts(defaults, overrides): + combined = defaults.copy() + combined.update(overrides) + return combined + + def set_trace_ids(): txn = current_transaction() if txn: @@ -31,155 +53,169 @@ def set_trace_ids(): trace.guid = "abcdefgh" -def exercise_record_log_event(message="A"): +def exercise_record_log_event(): set_trace_ids() - record_log_event(message, "ERROR") + record_log_event("no_other_arguments") + record_log_event("keyword_arguments", timestamp=1234, level="ERROR", attributes={"key": "value"}) + record_log_event("positional_arguments", "WARNING", 2345, {"key": "value"}) + record_log_event("serialized_attributes", attributes=_serialized_attributes) + + # Unsent due to message content missing + record_log_event("") + record_log_event(" ") + record_log_event(None) + record_log_event(None, attributes={"attributes_only": "value"}) -enable_log_forwarding = override_application_settings({"application_logging.forwarding.enabled": True}) + +enable_log_forwarding = override_application_settings( + {"application_logging.forwarding.enabled": True, "application_logging.forwarding.context_data.enabled": True} +) +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, "hostname": None, "entity.name": "Python Agent Test (agent_features)", "entity.guid": None} +_common_attributes_service_linking = { + "timestamp": None, + "hostname": None, + "entity.name": "Python Agent Test (agent_features)", + "entity.guid": None, +} _common_attributes_trace_linking = {"span.id": "abcdefgh", "trace.id": "abcdefgh12345678"} _common_attributes_trace_linking.update(_common_attributes_service_linking) -_test_record_log_event_inside_transaction_events = [{"message": "A", "level": "ERROR"}] -_test_record_log_event_inside_transaction_events[0].update(_common_attributes_trace_linking) + +_serialized_attributes = { + "str_attr": "Value", + "bytes_attr": b"value", + "int_attr": 1, + "dict_attr": {"key": "value"}, + "non_serializable_attr": NonSerializableObject(), + "non_printable_attr": NonPrintableObject(), +} + +_exercise_record_log_event_events = [ + {"message": "no_other_arguments", "level": "UNKNOWN"}, + {"message": "keyword_arguments", "level": "ERROR", "timestamp": 1234, "context.key": "value"}, + {"message": "positional_arguments", "level": "WARNING", "timestamp": 2345, "context.key": "value"}, + { + "message": "serialized_attributes", + "context.str_attr": "Value", + "context.bytes_attr": b"value", + "context.int_attr": "1", + "context.dict_attr": '{"key":"value"}', + "context.non_serializable_attr": "", + "context.non_printable_attr": "", + }, +] +_exercise_record_log_event_inside_transaction_events = [ + combine_dicts(_common_attributes_trace_linking, log) for log in _exercise_record_log_event_events +] +_exercise_record_log_event_outside_transaction_events = [ + combine_dicts(_common_attributes_service_linking, log) for log in _exercise_record_log_event_events +] + +# Test Log Forwarding @enable_log_forwarding def test_record_log_event_inside_transaction(): - @validate_log_events(_test_record_log_event_inside_transaction_events) - @validate_log_event_count(1) + @validate_log_events(_exercise_record_log_event_inside_transaction_events) + @validate_log_event_count(len(_exercise_record_log_event_inside_transaction_events)) @background_task() def test(): exercise_record_log_event() - - test() + test() -_test_record_log_event_outside_transaction_events = [{"message": "A", "level": "ERROR"}] -_test_record_log_event_outside_transaction_events[0].update(_common_attributes_service_linking) @enable_log_forwarding @reset_core_stats_engine() def test_record_log_event_outside_transaction(): - @validate_log_events_outside_transaction(_test_record_log_event_outside_transaction_events) - @validate_log_event_count_outside_transaction(1) + @validate_log_events_outside_transaction(_exercise_record_log_event_outside_transaction_events) + @validate_log_event_count_outside_transaction(len(_exercise_record_log_event_outside_transaction_events)) def test(): exercise_record_log_event() test() -_test_record_log_event_unknown_level_inside_transaction_events = [{"message": "A", "level": "UNKNOWN"}] -_test_record_log_event_unknown_level_inside_transaction_events[0].update(_common_attributes_trace_linking) - @enable_log_forwarding -def test_record_log_event_unknown_level_inside_transaction(): - @validate_log_events(_test_record_log_event_unknown_level_inside_transaction_events) - @validate_log_event_count(1) +def test_ignored_transaction_logs_not_forwarded(): + @validate_log_event_count(0) @background_task() def test(): - set_trace_ids() - record_log_event("A") - - test() - + ignore_transaction() + exercise_record_log_event() -_test_record_log_event_unknown_level_outside_transaction_events = [{"message": "A", "level": "UNKNOWN"}] -_test_record_log_event_unknown_level_outside_transaction_events[0].update(_common_attributes_service_linking) + test() -@enable_log_forwarding -@reset_core_stats_engine() -def test_record_log_event_unknown_level_outside_transaction(): - @validate_log_events_outside_transaction(_test_record_log_event_unknown_level_outside_transaction_events) - @validate_log_event_count_outside_transaction(1) - def test(): - set_trace_ids() - record_log_event("A") - test() +# Test Message Truncation +_test_log_event_truncation_events = [{"message": "A" * 32768}] @enable_log_forwarding -def test_record_log_event_empty_message_inside_transaction(): - @validate_log_event_count(0) +def test_log_event_truncation_inside_transaction(): + @validate_log_events(_test_log_event_truncation_events) + @validate_log_event_count(1) @background_task() def test(): - exercise_record_log_event("") - + record_log_event("A" * 33000) + test() @enable_log_forwarding @reset_core_stats_engine() -def test_record_log_event_empty_message_outside_transaction(): - @validate_log_event_count_outside_transaction(0) +def test_log_event_truncation_outside_transaction(): + @validate_log_events_outside_transaction(_test_log_event_truncation_events) + @validate_log_event_count_outside_transaction(1) def test(): - exercise_record_log_event("") + record_log_event("A" * 33000) test() -@enable_log_forwarding -def test_record_log_event_whitespace_inside_transaction(): +# Test Log Forwarding Settings + +@disable_log_forwarding +def test_disabled_record_log_event_inside_transaction(): @validate_log_event_count(0) @background_task() def test(): - exercise_record_log_event(" ") + exercise_record_log_event() test() -@enable_log_forwarding +@disable_log_forwarding @reset_core_stats_engine() -def test_record_log_event_whitespace_outside_transaction(): +def test_disabled_record_log_event_outside_transaction(): @validate_log_event_count_outside_transaction(0) def test(): - exercise_record_log_event(" ") - - test() - - -@enable_log_forwarding -def test_ignored_transaction_logs_not_forwarded(): - @validate_log_event_count(0) - @background_task() - def test(): - ignore_transaction() exercise_record_log_event() test() +# Test Log Attribute Settings -_test_log_event_truncation_events = [{"message": "A" * 32768, "level": "ERROR"}] -_test_log_event_truncation_events[0].update(_common_attributes_trace_linking) - -@enable_log_forwarding -def test_log_event_truncation(): - @validate_log_events(_test_log_event_truncation_events) +@disable_log_attributes +def test_attributes_disabled_inside_transaction(): + @validate_log_events([{"message": "A"}], forgone_attrs=["context.key"]) @validate_log_event_count(1) @background_task() def test(): - exercise_record_log_event("A" * 33000) - - test() + record_log_event("A", attributes={"key": "value"}) - -@disable_log_forwarding -def test_record_log_event_inside_transaction(): - @validate_log_event_count(0) - @background_task() - def test(): - exercise_record_log_event() - test() -@disable_log_forwarding +@disable_log_attributes @reset_core_stats_engine() -def test_record_log_event_outside_transaction(): - @validate_log_event_count_outside_transaction(0) +def test_attributes_disabled_outside_transaction(): + @validate_log_events_outside_transaction([{"message": "A"}], forgone_attrs=["context.key"]) + @validate_log_event_count_outside_transaction(1) def test(): - exercise_record_log_event() + record_log_event("A", attributes={"key": "value"}) test() diff --git a/tests/agent_features/test_logs_in_context.py b/tests/agent_features/test_logs_in_context.py index 90b6c9267..01abb853f 100644 --- a/tests/agent_features/test_logs_in_context.py +++ b/tests/agent_features/test_logs_in_context.py @@ -50,9 +50,15 @@ def log_buffer(caplog): class NonPrintableObject(object): def __str__(self): raise RuntimeError("Unable to print object.") + + __repr__ = __str__ - def __repr__(self): - raise RuntimeError("Unable to print object.") + +class NonSerializableObject(object): + def __str__(self): + return "<%s object>" % self.__class__.__name__ + + __repr__ = __str__ def test_newrelic_logger_no_error(log_buffer): @@ -63,7 +69,8 @@ def test_newrelic_logger_no_error(log_buffer): "null": None, "array": [1, 2, 3], "bool": True, - "non_serializable": {"set"}, + "set": {"set"}, + "non_serializable": NonSerializableObject(), "non_printable": NonPrintableObject(), "object": { "first": "bar", @@ -101,7 +108,8 @@ def test_newrelic_logger_no_error(log_buffer): u"extra.null": None, u"extra.array": [1, 2, 3], u"extra.bool": True, - u"extra.non_serializable": u"set(['set'])" if six.PY2 else u"{'set'}", + u"extra.set": u'["set"]', + u"extra.non_serializable": u"", u"extra.non_printable": u"", u"extra.object": { u"first": u"bar", diff --git a/tests/logger_logging/test_attribute_forwarding.py b/tests/logger_logging/test_attribute_forwarding.py new file mode 100644 index 000000000..04879ace6 --- /dev/null +++ b/tests/logger_logging/test_attribute_forwarding.py @@ -0,0 +1,54 @@ +# Copyright 2010 New Relic, Inc. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +from newrelic.api.background_task import background_task +from testing_support.fixtures import 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 validate_log_event_count_outside_transaction +from testing_support.validators.validate_log_events import validate_log_events +from testing_support.validators.validate_log_events_outside_transaction import validate_log_events_outside_transaction +from testing_support.fixtures import override_application_settings + + +_event_attributes = {"message": "A", "context.key": "value"} + + +def exercise_logging(logger): + logger.error("A", extra={"key": "value"}) + assert len(logger.caplog.records) == 1 + +@override_application_settings({ + "application_logging.forwarding.context_data.enabled": True, +}) +def test_attributes_inside_transaction(logger): + @validate_log_events([_event_attributes]) + @validate_log_event_count(1) + @background_task() + def test(): + exercise_logging(logger) + + test() + + +@reset_core_stats_engine() +@override_application_settings({ + "application_logging.forwarding.context_data.enabled": True, +}) +def test_attributes_outside_transaction(logger): + @validate_log_events_outside_transaction([_event_attributes]) + @validate_log_event_count_outside_transaction(1) + def test(): + exercise_logging(logger) + + test() diff --git a/tests/logger_logging/test_logging_handler.py b/tests/logger_logging/test_logging_handler.py index 9bf488582..25b1cc804 100644 --- a/tests/logger_logging/test_logging_handler.py +++ b/tests/logger_logging/test_logging_handler.py @@ -18,12 +18,18 @@ from newrelic.api.background_task import background_task from newrelic.api.log import NewRelicLogForwardingHandler -from testing_support.fixtures import reset_core_stats_engine +from testing_support.fixtures import reset_core_stats_engine, override_application_settings from testing_support.validators.validate_log_event_count import validate_log_event_count from testing_support.validators.validate_log_event_count_outside_transaction import validate_log_event_count_outside_transaction from testing_support.validators.validate_function_called import validate_function_called +from testing_support.validators.validate_log_events import validate_log_events +from testing_support.validators.validate_log_events_outside_transaction import validate_log_events_outside_transaction +from newrelic.api.transaction import current_transaction +from newrelic.api.time_trace import current_trace +_common_attributes_service_linking = {"timestamp": None, "hostname": None, "entity.name": "Python Agent Test (logger_logging)", "entity.guid": None} +_common_attributes_trace_linking = {"span.id": "abcdefgh", "trace.id": "abcdefgh12345678"} @pytest.fixture(scope="function") @@ -43,12 +49,26 @@ def logger(conf_logger, uninstrument_logging): conf_logger.removeHandler(handler) +def set_trace_ids(): + txn = current_transaction() + if txn: + txn._trace_id = "abcdefgh12345678" + trace = current_trace() + if trace: + trace.guid = "abcdefgh" + + def exercise_logging(logger): - logger.warning("C") + set_trace_ids() + logger.warning("C", extra={"key": "value"}) assert len(logger.caplog.records) == 1 +@override_application_settings({ + "application_logging.forwarding.context_data.enabled": True, +}) def test_handler_inside_transaction(logger): + @validate_log_events([{"message": "C", "level": "WARNING", "timestamp": None, "hostname": None, "entity.name": "Python Agent Test (logger_logging)", "entity.guid": None, "span.id": "abcdefgh", "trace.id": "abcdefgh12345678", "context.key": "value"}]) @validate_log_event_count(1) @validate_function_called("newrelic.api.log", "NewRelicLogForwardingHandler.emit") @background_task() @@ -59,7 +79,11 @@ def test(): @reset_core_stats_engine() +@override_application_settings({ + "application_logging.forwarding.context_data.enabled": True, +}) def test_handler_outside_transaction(logger): + @validate_log_events_outside_transaction([{"message": "C", "level": "WARNING", "timestamp": None, "hostname": None, "entity.name": "Python Agent Test (logger_logging)", "entity.guid": None, "context.key": "value"}]) @validate_log_event_count_outside_transaction(1) @validate_function_called("newrelic.api.log", "NewRelicLogForwardingHandler.emit") def test(): diff --git a/tests/logger_loguru/conftest.py b/tests/logger_loguru/conftest.py index 65eaf4ab8..55fc7edd6 100644 --- a/tests/logger_loguru/conftest.py +++ b/tests/logger_loguru/conftest.py @@ -53,10 +53,15 @@ def emit(self, record): @pytest.fixture(scope="function") def logger(): import loguru + _logger = loguru.logger + _logger.configure(extra={"global_extra": "global_value"}) + caplog = CaplogHandler() handler_id = _logger.add(caplog, level="WARNING", format="{message}") _logger.caplog = caplog + yield _logger + del caplog.records[:] _logger.remove(handler_id) diff --git a/tests/logger_loguru/test_attribute_forwarding.py b/tests/logger_loguru/test_attribute_forwarding.py new file mode 100644 index 000000000..bb5da5362 --- /dev/null +++ b/tests/logger_loguru/test_attribute_forwarding.py @@ -0,0 +1,54 @@ +# Copyright 2010 New Relic, Inc. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +from newrelic.api.background_task import background_task +from testing_support.fixtures import 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 validate_log_event_count_outside_transaction +from testing_support.validators.validate_log_events import validate_log_events +from testing_support.validators.validate_log_events_outside_transaction import validate_log_events_outside_transaction +from testing_support.fixtures import override_application_settings + + +_event_attributes = {"message": "A", "context.key": "value"} + + +def exercise_logging(logger): + logger.bind(key="value").error("A") + assert len(logger.caplog.records) == 1 + +@override_application_settings({ + "application_logging.forwarding.context_data.enabled": True, +}) +def test_attributes_inside_transaction(logger): + @validate_log_events([_event_attributes]) + @validate_log_event_count(1) + @background_task() + def test(): + exercise_logging(logger) + + test() + + +@reset_core_stats_engine() +@override_application_settings({ + "application_logging.forwarding.context_data.enabled": True, +}) +def test_attributes_outside_transaction(logger): + @validate_log_events_outside_transaction([_event_attributes]) + @validate_log_event_count_outside_transaction(1) + def test(): + exercise_logging(logger) + + test() diff --git a/tests/testing_support/validators/validate_log_event_count.py b/tests/testing_support/validators/validate_log_event_count.py index 243364d2d..e4f58a60a 100644 --- a/tests/testing_support/validators/validate_log_event_count.py +++ b/tests/testing_support/validators/validate_log_event_count.py @@ -47,7 +47,7 @@ def _validate_log_event_count(wrapped, instance, args, kwargs): record_called[:] = [] recorded_logs[:] = [] - assert count == len(logs), len(logs) + assert count == len(logs), "Expected %d, Got %d" % (count, len(logs)) return val diff --git a/tests/testing_support/validators/validate_log_event_count_outside_transaction.py b/tests/testing_support/validators/validate_log_event_count_outside_transaction.py index 8f1337df8..8dd29c22e 100644 --- a/tests/testing_support/validators/validate_log_event_count_outside_transaction.py +++ b/tests/testing_support/validators/validate_log_event_count_outside_transaction.py @@ -48,7 +48,7 @@ def _validate_log_event_count_outside_transaction(wrapped, instance, args, kwarg record_called[:] = [] recorded_logs[:] = [] - assert count == len(logs), len(logs) + assert count == len(logs), "Expected %d, Got %d" % (count, len(logs)) return val diff --git a/tests/testing_support/validators/validate_log_events.py b/tests/testing_support/validators/validate_log_events.py index aa6159512..c8618b390 100644 --- a/tests/testing_support/validators/validate_log_events.py +++ b/tests/testing_support/validators/validate_log_events.py @@ -20,7 +20,10 @@ function_wrapper) from testing_support.fixtures import catch_background_exceptions -def validate_log_events(events): +def validate_log_events(events=None, forgone_attrs=None): + events = events or [{}] # Empty event allows assertions based on only forgone attrs to still run and validate + forgone_attrs = forgone_attrs or [] + @function_wrapper def _validate_wrapper(wrapped, instance, args, kwargs): @@ -54,14 +57,14 @@ def _validate_log_events(wrapped, instance, args, kwargs): matching_log_events = 0 mismatches = [] for captured in logs: - if _check_log_attributes(expected, captured, mismatches): + if _check_log_attributes(expected, 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, captured, mismatches): + def _check_log_attributes(expected, forgone_attrs, captured, mismatches): for key, value in six.iteritems(expected): if hasattr(captured, key): captured_value = getattr(captured, key, None) @@ -76,6 +79,14 @@ def _check_log_attributes(expected, captured, mismatches): mismatches.append("key: %s, value:<%s><%s>" % (key, value, captured_value)) return False + for key in forgone_attrs: + if hasattr(captured, key): + mismatches.append("forgone_key: %s, value:<%s>" % (key, getattr(captured, key, None))) + return False + elif key in captured.attributes: + mismatches.append("forgone_key: %s, value:<%s>" % (key, captured.attributes[key])) + return False + return True def _log_details(matching_log_events, captured, mismatches): diff --git a/tests/testing_support/validators/validate_log_events_outside_transaction.py b/tests/testing_support/validators/validate_log_events_outside_transaction.py index 4bc941965..35c89a362 100644 --- a/tests/testing_support/validators/validate_log_events_outside_transaction.py +++ b/tests/testing_support/validators/validate_log_events_outside_transaction.py @@ -20,7 +20,10 @@ from newrelic.packages import six -def validate_log_events_outside_transaction(events): +def validate_log_events_outside_transaction(events=None, forgone_attrs=None): + events = events or [{}] # Empty event allows assertions based on only forgone attrs to still run and validate + forgone_attrs = forgone_attrs or [] + @function_wrapper def _validate_wrapper(wrapped, instance, args, kwargs): @@ -52,13 +55,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, captured, mismatches): + if _check_log_attributes(expected, 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, captured, mismatches): + + def _check_log_attributes(expected, forgone_attrs, captured, mismatches): for key, value in six.iteritems(expected): if hasattr(captured, key): captured_value = getattr(captured, key, None) @@ -73,6 +77,14 @@ def _check_log_attributes(expected, captured, mismatches): mismatches.append("key: %s, value:<%s><%s>" % (key, value, captured_value)) return False + for key in forgone_attrs: + if hasattr(captured, key): + mismatches.append("forgone_key: %s, value:<%s>" % (key, getattr(captured, key, None))) + return False + elif key in captured.attributes: + mismatches.append("forgone_key: %s, value:<%s>" % (key, captured.attributes[key])) + return False + return True def _log_details(matching_log_events, captured, mismatches): From fb1f47dc88f3b38bc3758feae387a940007d1318 Mon Sep 17 00:00:00 2001 From: Timothy Pansino <11214426+TimPansino@users.noreply.github.com> Date: Wed, 20 Dec 2023 17:00:47 -0800 Subject: [PATCH 2/9] Log Attribute Filtering (#1008) * Expand validator for log events * Add settings for context data filtering * Add attribute filtering for log events * Linting * Apply suggestions from code review * Remove none check on attributes --- newrelic/api/application.py | 5 +- newrelic/api/log.py | 6 +- newrelic/api/transaction.py | 14 +- newrelic/common/encoding_utils.py | 174 +++++++++--------- newrelic/config.py | 2 + newrelic/core/agent.py | 4 +- newrelic/core/application.py | 8 +- newrelic/core/attribute.py | 27 +++ newrelic/core/attribute_filter.py | 81 ++++---- newrelic/core/config.py | 6 + newrelic/core/stats_engine.py | 13 +- newrelic/hooks/logger_logging.py | 4 +- tests/agent_features/test_log_events.py | 138 ++++++++++++-- tests/agent_features/test_logs_in_context.py | 88 +++++---- .../test_attribute_forwarding.py | 33 ++-- tests/logger_logging/test_logging_handler.py | 78 ++++++-- tests/logger_loguru/conftest.py | 9 +- .../test_attribute_forwarding.py | 33 ++-- .../validators/validate_log_event_count.py | 8 +- ...ate_log_event_count_outside_transaction.py | 8 +- .../validators/validate_log_events.py | 39 ++-- ...validate_log_events_outside_transaction.py | 26 ++- 22 files changed, 518 insertions(+), 286 deletions(-) diff --git a/newrelic/api/application.py b/newrelic/api/application.py index 9297509bc..ebc8356a7 100644 --- a/newrelic/api/application.py +++ b/newrelic/api/application.py @@ -22,7 +22,6 @@ class Application(object): - _lock = threading.Lock() _instances = {} @@ -164,7 +163,9 @@ def record_transaction(self, data): 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, attributes=attributes, 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 index 2c372117b..cdd6737e3 100644 --- a/newrelic/api/log.py +++ b/newrelic/api/log.py @@ -21,8 +21,8 @@ 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.object_names import parse_exc_info from newrelic.common.encoding_utils import safe_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 @@ -133,8 +133,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 diff --git a/newrelic/api/transaction.py b/newrelic/api/transaction.py index d0164eaf2..26b6bfa4a 100644 --- a/newrelic/api/transaction.py +++ b/newrelic/api/transaction.py @@ -55,6 +55,7 @@ create_attributes, create_user_attributes, process_user_attribute, + resolve_logging_context_attributes, truncate, ) from newrelic.core.attribute_filter import ( @@ -310,7 +311,7 @@ def __init__(self, application, enabled=None, source=None): self.synthetics_job_id = None self.synthetics_monitor_id = None self.synthetics_header = None - + # Synthetics Info Header self.synthetics_type = None self.synthetics_initiator = None @@ -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) diff --git a/newrelic/common/encoding_utils.py b/newrelic/common/encoding_utils.py index e89573324..f075d42d3 100644 --- a/newrelic/common/encoding_utils.py +++ b/newrelic/common/encoding_utils.py @@ -31,14 +31,14 @@ from newrelic.packages import six -HEXDIGLC_RE = re.compile('^[0-9a-f]+$') -DELIMITER_FORMAT_RE = re.compile('[ \t]*,[ \t]*') +HEXDIGLC_RE = re.compile("^[0-9a-f]+$") +DELIMITER_FORMAT_RE = re.compile("[ \t]*,[ \t]*") PARENT_TYPE = { - '0': 'App', - '1': 'Browser', - '2': 'Mobile', + "0": "App", + "1": "Browser", + "2": "Mobile", } -BASE64_DECODE_STR = getattr(base64, 'decodestring', None) +BASE64_DECODE_STR = getattr(base64, "decodestring", None) # Functions for encoding/decoding JSON. These wrappers are used in order @@ -48,6 +48,7 @@ # be supplied as key word arguments to allow the wrappers to supply # defaults. + def json_encode(obj, **kwargs): _kwargs = {} @@ -79,21 +80,21 @@ def json_encode(obj, **kwargs): # The third is eliminate white space after separators to trim the # size of the data being sent. - if type(b'') is type(''): # NOQA - _kwargs['encoding'] = 'latin-1' + if type(b"") is type(""): # NOQA + _kwargs["encoding"] = "latin-1" def _encode(o): if isinstance(o, bytes): - return o.decode('latin-1') + return o.decode("latin-1") elif isinstance(o, types.GeneratorType): return list(o) - elif hasattr(o, '__iter__'): + elif hasattr(o, "__iter__"): return list(iter(o)) - raise TypeError(repr(o) + ' is not JSON serializable') + raise TypeError(repr(o) + " is not JSON serializable") - _kwargs['default'] = _encode + _kwargs["default"] = _encode - _kwargs['separators'] = (',', ':') + _kwargs["separators"] = (",", ":") # We still allow supplied arguments to override internal defaults if # necessary, but the caller must be sure they aren't dependent on @@ -116,7 +117,7 @@ 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 @@ -147,7 +148,7 @@ def xor_cipher_genkey(key, length=None): """ - return bytearray(key[:length], encoding='ascii') + return bytearray(key[:length], encoding="ascii") def xor_cipher_encrypt(text, key): @@ -213,8 +214,8 @@ def xor_cipher_encrypt_base64(text, key): # isn't UTF-8 and so fail with a Unicode decoding error. if isinstance(text, bytes): - text = text.decode('latin-1') - text = text.encode('utf-8').decode('latin-1') + text = text.decode("latin-1") + text = text.encode("utf-8").decode("latin-1") result = base64.b64encode(bytes(xor_cipher_encrypt(text, key))) @@ -225,7 +226,7 @@ def xor_cipher_encrypt_base64(text, key): # produces characters within that codeset. if six.PY3: - return result.decode('ascii') + return result.decode("ascii") return result @@ -246,7 +247,7 @@ def xor_cipher_decrypt_base64(text, key): result = xor_cipher_decrypt(bytearray(base64.b64decode(text)), key) - return bytes(result).decode('utf-8') + return bytes(result).decode("utf-8") obfuscate = xor_cipher_encrypt_base64 @@ -263,13 +264,13 @@ def unpack_field(field): """ if not isinstance(field, bytes): - field = field.encode('UTF-8') + field = field.encode("UTF-8") - data = getattr(base64, 'decodebytes', BASE64_DECODE_STR)(field) + data = getattr(base64, "decodebytes", BASE64_DECODE_STR)(field) data = zlib.decompress(data) if isinstance(data, bytes): - data = data.decode('Latin-1') + data = data.decode("Latin-1") data = json_decode(data) return data @@ -283,13 +284,13 @@ def generate_path_hash(name, seed): """ - rotated = ((seed << 1) | (seed >> 31)) & 0xffffffff + rotated = ((seed << 1) | (seed >> 31)) & 0xFFFFFFFF if not isinstance(name, bytes): - name = name.encode('UTF-8') + name = name.encode("UTF-8") - path_hash = (rotated ^ int(hashlib.md5(name).hexdigest()[-8:], base=16)) - return '%08x' % path_hash + path_hash = rotated ^ int(hashlib.md5(name).hexdigest()[-8:], base=16) + return "%08x" % path_hash def base64_encode(text): @@ -314,11 +315,11 @@ def base64_encode(text): # and so fail with a Unicode decoding error. if isinstance(text, bytes): - text = text.decode('latin-1') - text = text.encode('utf-8').decode('latin-1') + text = text.decode("latin-1") + text = text.encode("utf-8").decode("latin-1") # Re-encode as utf-8 when passing to b64 encoder - result = base64.b64encode(text.encode('utf-8')) + result = base64.b64encode(text.encode("utf-8")) # The result from base64 encoding will be a byte string but since # dealing with byte strings in Python 2 and Python 3 is quite @@ -327,7 +328,7 @@ def base64_encode(text): # produces characters within that codeset. if six.PY3: - return result.decode('ascii') + return result.decode("ascii") return result @@ -337,7 +338,7 @@ def base64_decode(text): the decoded text is UTF-8 encoded. """ - return base64.b64decode(text).decode('utf-8') + return base64.b64decode(text).decode("utf-8") def gzip_compress(text): @@ -348,9 +349,9 @@ def gzip_compress(text): compressed_data = io.BytesIO() if six.PY3 and isinstance(text, str): - text = text.encode('utf-8') + text = text.encode("utf-8") - with gzip.GzipFile(fileobj=compressed_data, mode='wb') as f: + with gzip.GzipFile(fileobj=compressed_data, mode="wb") as f: f.write(text) return compressed_data.getvalue() @@ -363,7 +364,7 @@ def gzip_decompress(payload): """ data_bytes = io.BytesIO(payload) decoded_data = gzip.GzipFile(fileobj=data_bytes).read() - return decoded_data.decode('utf-8') + return decoded_data.decode("utf-8") def serverless_payload_encode(payload): @@ -381,7 +382,7 @@ def serverless_payload_encode(payload): def ensure_str(s): if not isinstance(s, six.string_types): try: - s = s.decode('utf-8') + s = s.decode("utf-8") except Exception: return return s @@ -393,8 +394,8 @@ def serverless_payload_decode(text): Python object. """ - if hasattr(text, 'decode'): - text = text.decode('utf-8') + if hasattr(text, "decode"): + text = text.decode("utf-8") decoded_bytes = base64.b64decode(text) uncompressed_data = gzip_decompress(decoded_bytes) @@ -407,8 +408,7 @@ def decode_newrelic_header(encoded_header, encoding_key): decoded_header = None if encoded_header: try: - decoded_header = json_decode(deobfuscate( - encoded_header, encoding_key)) + decoded_header = json_decode(deobfuscate(encoded_header, encoding_key)) except Exception: pass @@ -425,7 +425,6 @@ def convert_to_cat_metadata_value(nr_headers): class DistributedTracePayload(dict): - version = (0, 1) def text(self): @@ -460,17 +459,16 @@ def decode(cls, payload): class W3CTraceParent(dict): - def text(self): - if 'id' in self: - guid = self['id'] + if "id" in self: + guid = self["id"] else: - guid = '{:016x}'.format(random.getrandbits(64)) + guid = "{:016x}".format(random.getrandbits(64)) - return '00-{}-{}-{:02x}'.format( - self['tr'].lower().zfill(32), + return "00-{}-{}-{:02x}".format( + self["tr"].lower().zfill(32), guid, - int(self.get('sa', 0)), + int(self.get("sa", 0)), ) @classmethod @@ -479,7 +477,7 @@ def decode(cls, payload): if len(payload) < 55: return None - fields = payload.split('-', 4) + fields = payload.split("-", 4) # Expect that there are at least 4 fields if len(fields) < 4: @@ -492,11 +490,11 @@ def decode(cls, payload): return None # Version 255 is invalid - if version == 'ff': + if version == "ff": return None # Expect exactly 4 fields if version 00 - if version == '00' and len(fields) != 4: + if version == "00" and len(fields) != 4: return None # Check field lengths and values @@ -506,18 +504,15 @@ def decode(cls, payload): # trace_id or parent_id of all 0's are invalid trace_id, parent_id = fields[1:3] - if parent_id == '0' * 16 or trace_id == '0' * 32: + if parent_id == "0" * 16 or trace_id == "0" * 32: return None return cls(tr=trace_id, id=parent_id) class W3CTraceState(OrderedDict): - def text(self, limit=32): - return ','.join( - '{}={}'.format(k, v) - for k, v in itertools.islice(self.items(), limit)) + return ",".join("{}={}".format(k, v) for k, v in itertools.islice(self.items(), limit)) @classmethod def decode(cls, tracestate): @@ -525,9 +520,8 @@ def decode(cls, tracestate): vendors = cls() for entry in entries: - vendor_value = entry.split('=', 2) - if (len(vendor_value) != 2 or - any(len(v) > 256 for v in vendor_value)): + vendor_value = entry.split("=", 2) + if len(vendor_value) != 2 or any(len(v) > 256 for v in vendor_value): continue vendor, value = vendor_value @@ -537,36 +531,38 @@ def decode(cls, tracestate): class NrTraceState(dict): - FIELDS = ('ty', 'ac', 'ap', 'id', 'tx', 'sa', 'pr') + FIELDS = ("ty", "ac", "ap", "id", "tx", "sa", "pr") def text(self): - pr = self.get('pr', '') + pr = self.get("pr", "") if pr: - pr = ('%.6f' % pr).rstrip('0').rstrip('.') - - payload = '-'.join(( - '0-0', - self['ac'], - self['ap'], - self.get('id', ''), - self.get('tx', ''), - '1' if self.get('sa') else '0', - pr, - str(self['ti']), - )) - return '{}@nr={}'.format( - self.get('tk', self['ac']), + pr = ("%.6f" % pr).rstrip("0").rstrip(".") + + payload = "-".join( + ( + "0-0", + self["ac"], + self["ap"], + self.get("id", ""), + self.get("tx", ""), + "1" if self.get("sa") else "0", + pr, + str(self["ti"]), + ) + ) + return "{}@nr={}".format( + self.get("tk", self["ac"]), payload, ) @classmethod def decode(cls, payload, tk): - fields = payload.split('-', 9) + fields = payload.split("-", 9) if len(fields) >= 9 and all(fields[:4]) and fields[8]: data = cls(tk=tk) try: - data['ti'] = int(fields[8]) + data["ti"] = int(fields[8]) except: return @@ -574,24 +570,24 @@ def decode(cls, payload, tk): if value: data[name] = value - if data['ty'] in PARENT_TYPE: - data['ty'] = PARENT_TYPE[data['ty']] + if data["ty"] in PARENT_TYPE: + data["ty"] = PARENT_TYPE[data["ty"]] else: return - if 'sa' in data: - if data['sa'] == '1': - data['sa'] = True - elif data['sa'] == '0': - data['sa'] = False + if "sa" in data: + if data["sa"] == "1": + data["sa"] = True + elif data["sa"] == "0": + data["sa"] = False else: - data['sa'] = None + data["sa"] = None - if 'pr' in data: + if "pr" in data: try: - data['pr'] = float(fields[7]) + data["pr"] = float(fields[7]) except: - data['pr'] = None + data["pr"] = None return data @@ -609,7 +605,7 @@ def capitalize(string): def camel_case(string, upper=False): """ Convert a string of snake case to camel case. - + Setting upper=True will capitalize the first letter. Defaults to False, where no change is made to the first letter. """ string = ensure_str(string) @@ -630,6 +626,8 @@ def camel_case(string, upper=False): _snake_case_re = re.compile(r"([A-Z]+[a-z]*)") + + def snake_case(string): """Convert a string of camel case to snake case. Assumes no repeated runs of capital letters.""" string = ensure_str(string) diff --git a/newrelic/config.py b/newrelic/config.py index b1bff73a8..6782a0396 100644 --- a/newrelic/config.py +++ b/newrelic/config.py @@ -553,6 +553,8 @@ def _process_configuration(section): _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.forwarding.context_data.include", "get", _map_inc_excl_attributes) + _process_setting(section, "application_logging.forwarding.context_data.exclude", "get", _map_inc_excl_attributes) _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 index 376f90c9f..31cef43e8 100644 --- a/newrelic/core/agent.py +++ b/newrelic/core/agent.py @@ -339,7 +339,6 @@ def activate_application(self, app_name, linked_applications=None, timeout=None, with self._lock: application = self._applications.get(app_name, None) if not application: - process_id = os.getpid() if process_id != self._process_id: @@ -449,7 +448,6 @@ def register_data_source(self, source, application=None, name=None, settings=Non instance.register_data_source(source, name, settings, **properties) def remove_thread_utilization(self): - _logger.debug("Removing thread utilization data source from all applications") source_name = thread_utilization_data_source.__name__ @@ -565,7 +563,7 @@ 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, attributes=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 diff --git a/newrelic/core/application.py b/newrelic/core/application.py index dcdb21f64..b7f6fb27d 100644 --- a/newrelic/core/application.py +++ b/newrelic/core/application.py @@ -945,7 +945,9 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=None, if message: with self._stats_custom_lock: - event = self._stats_engine.record_log_event(message, level, timestamp, attributes=attributes, priority=priority) + event = self._stats_engine.record_log_event( + message, level, timestamp, attributes=attributes, priority=priority + ) if event: self._global_events_account += 1 @@ -1506,7 +1508,9 @@ def harvest(self, shutdown=False, flexible=False): # Send metrics self._active_session.send_metric_data(self._period_start, period_end, metric_data) if dimensional_metric_data: - self._active_session.send_dimensional_metric_data(self._period_start, period_end, dimensional_metric_data) + self._active_session.send_dimensional_metric_data( + self._period_start, period_end, dimensional_metric_data + ) _logger.debug("Done sending data for harvest of %r.", self._app_name) diff --git a/newrelic/core/attribute.py b/newrelic/core/attribute.py index 10ae8e459..04dfdec34 100644 --- a/newrelic/core/attribute.py +++ b/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,32 @@ 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(): + 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) diff --git a/newrelic/core/attribute_filter.py b/newrelic/core/attribute_filter.py index 8d4a93843..8cd26cb30 100644 --- a/newrelic/core/attribute_filter.py +++ b/newrelic/core/attribute_filter.py @@ -15,16 +15,17 @@ # Attribute "destinations" represented as bitfields. DST_NONE = 0x0 -DST_ALL = 0x3F -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_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): +class AttributeFilter(object): # Apply filtering rules to attributes. # # Upon initialization, an AttributeFilter object will take all attribute @@ -59,46 +60,45 @@ class AttributeFilter(object): # 4. Return the resulting bitfield after all rules have been applied. def __init__(self, flattened_settings): - self.enabled_destinations = self._set_enabled_destinations(flattened_settings) self.rules = self._build_rules(flattened_settings) self.cache = {} def __repr__(self): - return "" % ( - bin(self.enabled_destinations), self.rules) + return "" % (bin(self.enabled_destinations), self.rules) def _set_enabled_destinations(self, settings): - # Determines and returns bitfield representing attribute destinations enabled. enabled_destinations = DST_NONE - if settings.get('transaction_segments.attributes.enabled', None): + if settings.get("transaction_segments.attributes.enabled", None): enabled_destinations |= DST_TRANSACTION_SEGMENTS - if settings.get('span_events.attributes.enabled', None): + if settings.get("span_events.attributes.enabled", None): enabled_destinations |= DST_SPAN_EVENTS - if settings.get('transaction_tracer.attributes.enabled', None): + if settings.get("transaction_tracer.attributes.enabled", None): enabled_destinations |= DST_TRANSACTION_TRACER - if settings.get('transaction_events.attributes.enabled', None): + if settings.get("transaction_events.attributes.enabled", None): enabled_destinations |= DST_TRANSACTION_EVENTS - if settings.get('error_collector.attributes.enabled', None): + if settings.get("error_collector.attributes.enabled", None): enabled_destinations |= DST_ERROR_COLLECTOR - if settings.get('browser_monitoring.attributes.enabled', None): + if settings.get("browser_monitoring.attributes.enabled", None): enabled_destinations |= DST_BROWSER_MONITORING - if not settings.get('attributes.enabled', None): + 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 return enabled_destinations def _build_rules(self, settings): - # "Rule Templates" below are used for building AttributeFilterRules. # # Each tuple includes: @@ -107,26 +107,27 @@ def _build_rules(self, settings): # 3. Boolean that represents whether the setting is an "include" or not. rule_templates = ( - ('attributes.include', DST_ALL, True), - ('attributes.exclude', DST_ALL, False), - ('transaction_events.attributes.include', DST_TRANSACTION_EVENTS, True), - ('transaction_events.attributes.exclude', DST_TRANSACTION_EVENTS, False), - ('transaction_tracer.attributes.include', DST_TRANSACTION_TRACER, True), - ('transaction_tracer.attributes.exclude', DST_TRANSACTION_TRACER, False), - ('error_collector.attributes.include', DST_ERROR_COLLECTOR, True), - ('error_collector.attributes.exclude', DST_ERROR_COLLECTOR, False), - ('browser_monitoring.attributes.include', DST_BROWSER_MONITORING, True), - ('browser_monitoring.attributes.exclude', DST_BROWSER_MONITORING, False), - ('span_events.attributes.include', DST_SPAN_EVENTS, True), - ('span_events.attributes.exclude', DST_SPAN_EVENTS, False), - ('transaction_segments.attributes.include', DST_TRANSACTION_SEGMENTS, True), - ('transaction_segments.attributes.exclude', DST_TRANSACTION_SEGMENTS, False), + ("attributes.include", DST_ALL, True), + ("attributes.exclude", DST_ALL, False), + ("transaction_events.attributes.include", DST_TRANSACTION_EVENTS, True), + ("transaction_events.attributes.exclude", DST_TRANSACTION_EVENTS, False), + ("transaction_tracer.attributes.include", DST_TRANSACTION_TRACER, True), + ("transaction_tracer.attributes.exclude", DST_TRANSACTION_TRACER, False), + ("error_collector.attributes.include", DST_ERROR_COLLECTOR, True), + ("error_collector.attributes.exclude", DST_ERROR_COLLECTOR, False), + ("browser_monitoring.attributes.include", DST_BROWSER_MONITORING, True), + ("browser_monitoring.attributes.exclude", DST_BROWSER_MONITORING, False), + ("span_events.attributes.include", DST_SPAN_EVENTS, True), + ("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 = [] - for (setting_name, destination, is_include) in rule_templates: - + for setting_name, destination, is_include in rule_templates: for setting in settings.get(setting_name) or (): rule = AttributeFilterRule(setting, destination, is_include) rules.append(rule) @@ -157,16 +158,15 @@ def apply(self, name, default_destinations): self.cache[cache_index] = destinations return destinations -class AttributeFilterRule(object): +class AttributeFilterRule(object): def __init__(self, name, destinations, is_include): - self.name = name.rstrip('*') + self.name = name.rstrip("*") self.destinations = destinations self.is_include = is_include - self.is_wildcard = name.endswith('*') + self.is_wildcard = name.endswith("*") def _as_sortable(self): - # Represent AttributeFilterRule as a tuple that will sort properly. # # Sorting rules: @@ -207,8 +207,7 @@ def __ge__(self, other): return self._as_sortable() >= other._as_sortable() def __repr__(self): - return '(%s, %s, %s, %s)' % (self.name, bin(self.destinations), - self.is_wildcard, self.is_include) + return "(%s, %s, %s, %s)" % (self.name, bin(self.destinations), self.is_wildcard, self.is_include) def name_match(self, name): if self.is_wildcard: diff --git a/newrelic/core/config.py b/newrelic/core/config.py index aba1db10b..f627356c7 100644 --- a/newrelic/core/config.py +++ b/newrelic/core/config.py @@ -902,6 +902,12 @@ def default_otlp_host(host): _settings.application_logging.forwarding.context_data.enabled = _environ_as_bool( "NEW_RELIC_APPLICATION_LOGGING_FORWARDING_CONTEXT_DATA_ENABLED", default=False ) +_settings.application_logging.forwarding.context_data.include = _environ_as_set( + "NEW_RELIC_APPLICATION_LOGGING_FORWARDING_CONTEXT_DATA_INCLUDE", default="" +) +_settings.application_logging.forwarding.context_data.exclude = _environ_as_set( + "NEW_RELIC_APPLICATION_LOGGING_FORWARDING_CONTEXT_DATA_EXCLUDE", default="" +) _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 index c39ec5e6e..e09637ee9 100644 --- a/newrelic/core/stats_engine.py +++ b/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 @@ -1218,7 +1219,6 @@ 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, attributes=None, priority=None): settings = self.__settings if not ( @@ -1239,16 +1239,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: diff --git a/newrelic/hooks/logger_logging.py b/newrelic/hooks/logger_logging.py index 27fd7edc6..80cf0fd24 100644 --- a/newrelic/hooks/logger_logging.py +++ b/newrelic/hooks/logger_logging.py @@ -91,7 +91,9 @@ def wrap_callHandlers(wrapped, instance, args, kwargs): try: message = record.getMessage() attrs = filter_record_attributes(record) - record_log_event(message=message, level=level_name, timestamp=int(record.created * 1000), attributes=attrs) + record_log_event( + message=message, level=level_name, timestamp=int(record.created * 1000), attributes=attrs + ) except Exception: pass diff --git a/tests/agent_features/test_log_events.py b/tests/agent_features/test_log_events.py index b62d6a5fc..91585d2ff 100644 --- a/tests/agent_features/test_log_events.py +++ b/tests/agent_features/test_log_events.py @@ -12,22 +12,34 @@ # See the License for the specific language governing permissions and # limitations under the License. -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 testing_support.fixtures import override_application_settings, reset_core_stats_engine +import pytest +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 ( validate_log_event_count_outside_transaction, ) from testing_support.validators.validate_log_events import validate_log_events -from testing_support.validators.validate_log_events_outside_transaction import validate_log_events_outside_transaction +from testing_support.validators.validate_log_events_outside_transaction import ( + validate_log_events_outside_transaction, +) + +from newrelic.api.background_task import background_task +from newrelic.api.time_trace import current_trace +from newrelic.api.transaction import ( + current_transaction, + ignore_transaction, + record_log_event, +) +from newrelic.core.config import _parse_attributes class NonPrintableObject(object): def __str__(self): raise RuntimeError("Unable to print object.") - + __repr__ = __str__ @@ -71,10 +83,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 +105,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 +118,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": "", - "context.non_printable_attr": "", + "context.attr_value_too_long": "*" * 255, }, ] _exercise_record_log_event_inside_transaction_events = [ @@ -114,12 +130,21 @@ 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 +156,9 @@ 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 +181,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 +206,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 +226,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 +250,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() diff --git a/tests/agent_features/test_logs_in_context.py b/tests/agent_features/test_logs_in_context.py index 01abb853f..8693c0f08 100644 --- a/tests/agent_features/test_logs_in_context.py +++ b/tests/agent_features/test_logs_in_context.py @@ -50,7 +50,7 @@ def log_buffer(caplog): class NonPrintableObject(object): def __str__(self): raise RuntimeError("Unable to print object.") - + __repr__ = __str__ @@ -77,7 +77,7 @@ def test_newrelic_logger_no_error(log_buffer): "second": "baz", }, } - _logger.info(u"Hello %s", u"World", extra=extra) + _logger.info("Hello %s", "World", extra=extra) log_buffer.seek(0) message = json.load(log_buffer) @@ -95,25 +95,25 @@ def test_newrelic_logger_no_error(log_buffer): assert isinstance(line_number, int) expected = { - u"entity.name": u"Python Agent Test (agent_features)", - u"entity.type": u"SERVICE", - u"message": u"Hello World", - u"log.level": u"INFO", - u"logger.name": u"test_logs_in_context", - u"thread.name": u"MainThread", - u"process.name": u"MainProcess", - u"extra.string": u"foo", - u"extra.integer": 1, - u"extra.float": 1.23, - u"extra.null": None, - u"extra.array": [1, 2, 3], - u"extra.bool": True, - u"extra.set": u'["set"]', - u"extra.non_serializable": u"", - u"extra.non_printable": u"", - u"extra.object": { - u"first": u"bar", - u"second": u"baz", + "entity.name": "Python Agent Test (agent_features)", + "entity.type": "SERVICE", + "message": "Hello World", + "log.level": "INFO", + "logger.name": "test_logs_in_context", + "thread.name": "MainThread", + "process.name": "MainProcess", + "extra.string": "foo", + "extra.integer": 1, + "extra.float": 1.23, + "extra.null": None, + "extra.array": [1, 2, 3], + "extra.bool": True, + "extra.set": '["set"]', + "extra.non_serializable": "", + "extra.non_printable": "", + "extra.object": { + "first": "bar", + "second": "baz", }, } expected_extra_txn_keys = ( @@ -127,7 +127,6 @@ def test_newrelic_logger_no_error(log_buffer): assert set(message.keys()) == set(expected_extra_txn_keys) - class ExceptionForTest(ValueError): pass @@ -137,7 +136,7 @@ def test_newrelic_logger_error_inside_transaction(log_buffer): try: raise ExceptionForTest except ExceptionForTest: - _logger.exception(u"oops") + _logger.exception("oops") log_buffer.seek(0) message = json.load(log_buffer) @@ -155,16 +154,16 @@ def test_newrelic_logger_error_inside_transaction(log_buffer): assert isinstance(line_number, int) expected = { - u"entity.name": u"Python Agent Test (agent_features)", - u"entity.type": u"SERVICE", - u"message": u"oops", - u"log.level": u"ERROR", - u"logger.name": u"test_logs_in_context", - u"thread.name": u"MainThread", - u"process.name": u"MainProcess", - u"error.class": u"test_logs_in_context:ExceptionForTest", - u"error.message": u"", - u"error.expected": False, + "entity.name": "Python Agent Test (agent_features)", + "entity.type": "SERVICE", + "message": "oops", + "log.level": "ERROR", + "logger.name": "test_logs_in_context", + "thread.name": "MainThread", + "process.name": "MainProcess", + "error.class": "test_logs_in_context:ExceptionForTest", + "error.message": "", + "error.expected": False, } expected_extra_txn_keys = ( "trace.id", @@ -183,7 +182,7 @@ def test_newrelic_logger_error_outside_transaction(log_buffer): try: raise ExceptionForTest except ExceptionForTest: - _logger.exception(u"oops") + _logger.exception("oops") log_buffer.seek(0) message = json.load(log_buffer) @@ -201,15 +200,15 @@ def test_newrelic_logger_error_outside_transaction(log_buffer): assert isinstance(line_number, int) expected = { - u"entity.name": u"Python Agent Test (agent_features)", - u"entity.type": u"SERVICE", - u"message": u"oops", - u"log.level": u"ERROR", - u"logger.name": u"test_logs_in_context", - u"thread.name": u"MainThread", - u"process.name": u"MainProcess", - u"error.class": u"test_logs_in_context:ExceptionForTest", - u"error.message": u"", + "entity.name": "Python Agent Test (agent_features)", + "entity.type": "SERVICE", + "message": "oops", + "log.level": "ERROR", + "logger.name": "test_logs_in_context", + "thread.name": "MainThread", + "process.name": "MainProcess", + "error.class": "test_logs_in_context:ExceptionForTest", + "error.message": "", } expected_extra_txn_keys = ( "entity.guid", @@ -222,14 +221,13 @@ def test_newrelic_logger_error_outside_transaction(log_buffer): assert set(message.keys()) == set(expected_extra_txn_keys) - EXPECTED_KEYS_TXN = ( "trace.id", "span.id", "entity.name", "entity.type", "entity.guid", - "hostname", + "hostname", ) EXPECTED_KEYS_NO_TXN = EXPECTED_KEYS_TRACE_ENDED = ( diff --git a/tests/logger_logging/test_attribute_forwarding.py b/tests/logger_logging/test_attribute_forwarding.py index 04879ace6..eea549e70 100644 --- a/tests/logger_logging/test_attribute_forwarding.py +++ b/tests/logger_logging/test_attribute_forwarding.py @@ -12,14 +12,20 @@ # See the License for the specific language governing permissions and # limitations under the License. -from newrelic.api.background_task import background_task -from testing_support.fixtures import reset_core_stats_engine +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 validate_log_event_count_outside_transaction +from testing_support.validators.validate_log_event_count_outside_transaction import ( + validate_log_event_count_outside_transaction, +) from testing_support.validators.validate_log_events import validate_log_events -from testing_support.validators.validate_log_events_outside_transaction import validate_log_events_outside_transaction -from testing_support.fixtures import override_application_settings +from testing_support.validators.validate_log_events_outside_transaction import ( + validate_log_events_outside_transaction, +) +from newrelic.api.background_task import background_task _event_attributes = {"message": "A", "context.key": "value"} @@ -28,9 +34,12 @@ def exercise_logging(logger): logger.error("A", extra={"key": "value"}) assert len(logger.caplog.records) == 1 -@override_application_settings({ - "application_logging.forwarding.context_data.enabled": True, -}) + +@override_application_settings( + { + "application_logging.forwarding.context_data.enabled": True, + } +) def test_attributes_inside_transaction(logger): @validate_log_events([_event_attributes]) @validate_log_event_count(1) @@ -42,9 +51,11 @@ def test(): @reset_core_stats_engine() -@override_application_settings({ - "application_logging.forwarding.context_data.enabled": True, -}) +@override_application_settings( + { + "application_logging.forwarding.context_data.enabled": True, + } +) def test_attributes_outside_transaction(logger): @validate_log_events_outside_transaction([_event_attributes]) @validate_log_event_count_outside_transaction(1) diff --git a/tests/logger_logging/test_logging_handler.py b/tests/logger_logging/test_logging_handler.py index 25b1cc804..dce99f9f8 100644 --- a/tests/logger_logging/test_logging_handler.py +++ b/tests/logger_logging/test_logging_handler.py @@ -12,23 +12,35 @@ # See the License for the specific language governing permissions and # limitations under the License. -from conftest import logger as conf_logger import logging + import pytest +from conftest import logger as conf_logger +from testing_support.fixtures import ( + override_application_settings, + reset_core_stats_engine, +) +from testing_support.validators.validate_function_called import validate_function_called +from testing_support.validators.validate_log_event_count import validate_log_event_count +from testing_support.validators.validate_log_event_count_outside_transaction import ( + validate_log_event_count_outside_transaction, +) +from testing_support.validators.validate_log_events import validate_log_events +from testing_support.validators.validate_log_events_outside_transaction import ( + validate_log_events_outside_transaction, +) from newrelic.api.background_task import background_task from newrelic.api.log import NewRelicLogForwardingHandler -from testing_support.fixtures import reset_core_stats_engine, override_application_settings -from testing_support.validators.validate_log_event_count import validate_log_event_count -from testing_support.validators.validate_log_event_count_outside_transaction import validate_log_event_count_outside_transaction -from testing_support.validators.validate_function_called import validate_function_called -from testing_support.validators.validate_log_events import validate_log_events -from testing_support.validators.validate_log_events_outside_transaction import validate_log_events_outside_transaction -from newrelic.api.transaction import current_transaction from newrelic.api.time_trace import current_trace +from newrelic.api.transaction import current_transaction - -_common_attributes_service_linking = {"timestamp": None, "hostname": None, "entity.name": "Python Agent Test (logger_logging)", "entity.guid": None} +_common_attributes_service_linking = { + "timestamp": None, + "hostname": None, + "entity.name": "Python Agent Test (logger_logging)", + "entity.guid": None, +} _common_attributes_trace_linking = {"span.id": "abcdefgh", "trace.id": "abcdefgh12345678"} @@ -64,11 +76,27 @@ def exercise_logging(logger): assert len(logger.caplog.records) == 1 -@override_application_settings({ - "application_logging.forwarding.context_data.enabled": True, -}) +@override_application_settings( + { + "application_logging.forwarding.context_data.enabled": True, + } +) def test_handler_inside_transaction(logger): - @validate_log_events([{"message": "C", "level": "WARNING", "timestamp": None, "hostname": None, "entity.name": "Python Agent Test (logger_logging)", "entity.guid": None, "span.id": "abcdefgh", "trace.id": "abcdefgh12345678", "context.key": "value"}]) + @validate_log_events( + [ + { + "message": "C", + "level": "WARNING", + "timestamp": None, + "hostname": None, + "entity.name": "Python Agent Test (logger_logging)", + "entity.guid": None, + "span.id": "abcdefgh", + "trace.id": "abcdefgh12345678", + "context.key": "value", + } + ] + ) @validate_log_event_count(1) @validate_function_called("newrelic.api.log", "NewRelicLogForwardingHandler.emit") @background_task() @@ -79,11 +107,25 @@ def test(): @reset_core_stats_engine() -@override_application_settings({ - "application_logging.forwarding.context_data.enabled": True, -}) +@override_application_settings( + { + "application_logging.forwarding.context_data.enabled": True, + } +) def test_handler_outside_transaction(logger): - @validate_log_events_outside_transaction([{"message": "C", "level": "WARNING", "timestamp": None, "hostname": None, "entity.name": "Python Agent Test (logger_logging)", "entity.guid": None, "context.key": "value"}]) + @validate_log_events_outside_transaction( + [ + { + "message": "C", + "level": "WARNING", + "timestamp": None, + "hostname": None, + "entity.name": "Python Agent Test (logger_logging)", + "entity.guid": None, + "context.key": "value", + } + ] + ) @validate_log_event_count_outside_transaction(1) @validate_function_called("newrelic.api.log", "NewRelicLogForwardingHandler.emit") def test(): diff --git a/tests/logger_loguru/conftest.py b/tests/logger_loguru/conftest.py index 55fc7edd6..1be79f89b 100644 --- a/tests/logger_loguru/conftest.py +++ b/tests/logger_loguru/conftest.py @@ -13,10 +13,12 @@ # limitations under the License. import logging -import pytest - -from testing_support.fixtures import collector_agent_registration_fixture, collector_available_fixture # noqa: F401; pylint: disable=W0611 +import pytest +from testing_support.fixtures import ( # noqa: F401; pylint: disable=W0611 + collector_agent_registration_fixture, + collector_available_fixture, +) _default_settings = { "transaction_tracer.explain_threshold": 0.0, @@ -42,6 +44,7 @@ class CaplogHandler(logging.StreamHandler): To prevent possible issues with pytest's monkey patching use a custom Caplog handler to capture all records """ + def __init__(self, *args, **kwargs): self.records = [] super(CaplogHandler, self).__init__(*args, **kwargs) diff --git a/tests/logger_loguru/test_attribute_forwarding.py b/tests/logger_loguru/test_attribute_forwarding.py index bb5da5362..d81608e3c 100644 --- a/tests/logger_loguru/test_attribute_forwarding.py +++ b/tests/logger_loguru/test_attribute_forwarding.py @@ -12,14 +12,20 @@ # See the License for the specific language governing permissions and # limitations under the License. -from newrelic.api.background_task import background_task -from testing_support.fixtures import reset_core_stats_engine +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 validate_log_event_count_outside_transaction +from testing_support.validators.validate_log_event_count_outside_transaction import ( + validate_log_event_count_outside_transaction, +) from testing_support.validators.validate_log_events import validate_log_events -from testing_support.validators.validate_log_events_outside_transaction import validate_log_events_outside_transaction -from testing_support.fixtures import override_application_settings +from testing_support.validators.validate_log_events_outside_transaction import ( + validate_log_events_outside_transaction, +) +from newrelic.api.background_task import background_task _event_attributes = {"message": "A", "context.key": "value"} @@ -28,9 +34,12 @@ def exercise_logging(logger): logger.bind(key="value").error("A") assert len(logger.caplog.records) == 1 -@override_application_settings({ - "application_logging.forwarding.context_data.enabled": True, -}) + +@override_application_settings( + { + "application_logging.forwarding.context_data.enabled": True, + } +) def test_attributes_inside_transaction(logger): @validate_log_events([_event_attributes]) @validate_log_event_count(1) @@ -42,9 +51,11 @@ def test(): @reset_core_stats_engine() -@override_application_settings({ - "application_logging.forwarding.context_data.enabled": True, -}) +@override_application_settings( + { + "application_logging.forwarding.context_data.enabled": True, + } +) def test_attributes_outside_transaction(logger): @validate_log_events_outside_transaction([_event_attributes]) @validate_log_event_count_outside_transaction(1) diff --git a/tests/testing_support/validators/validate_log_event_count.py b/tests/testing_support/validators/validate_log_event_count.py index e4f58a60a..13f6c4e47 100644 --- a/tests/testing_support/validators/validate_log_event_count.py +++ b/tests/testing_support/validators/validate_log_event_count.py @@ -14,14 +14,14 @@ import copy -from newrelic.common.object_wrapper import (transient_function_wrapper, - function_wrapper) from testing_support.fixtures import catch_background_exceptions +from newrelic.common.object_wrapper import function_wrapper, transient_function_wrapper + + def validate_log_event_count(count=1): @function_wrapper def _validate_wrapper(wrapped, instance, args, kwargs): - record_called = [] recorded_logs = [] @@ -43,7 +43,7 @@ def _validate_log_event_count(wrapped, instance, args, kwargs): if count: assert record_called logs = copy.copy(recorded_logs) - + record_called[:] = [] recorded_logs[:] = [] diff --git a/tests/testing_support/validators/validate_log_event_count_outside_transaction.py b/tests/testing_support/validators/validate_log_event_count_outside_transaction.py index 8dd29c22e..e04c9df85 100644 --- a/tests/testing_support/validators/validate_log_event_count_outside_transaction.py +++ b/tests/testing_support/validators/validate_log_event_count_outside_transaction.py @@ -14,14 +14,14 @@ import copy -from newrelic.common.object_wrapper import (transient_function_wrapper, - function_wrapper) from testing_support.fixtures import catch_background_exceptions +from newrelic.common.object_wrapper import function_wrapper, transient_function_wrapper + + def validate_log_event_count_outside_transaction(count=1): @function_wrapper def _validate_wrapper(wrapped, instance, args, kwargs): - record_called = [] recorded_logs = [] @@ -44,7 +44,7 @@ def _validate_log_event_count_outside_transaction(wrapped, instance, args, kwarg if count: assert record_called logs = copy.copy(recorded_logs) - + record_called[:] = [] recorded_logs[:] = [] diff --git a/tests/testing_support/validators/validate_log_events.py b/tests/testing_support/validators/validate_log_events.py index c8618b390..4008d0e52 100644 --- a/tests/testing_support/validators/validate_log_events.py +++ b/tests/testing_support/validators/validate_log_events.py @@ -14,19 +14,21 @@ import copy +from testing_support.fixtures import catch_background_exceptions + +from newrelic.common.object_wrapper import function_wrapper, transient_function_wrapper from newrelic.packages import six -from newrelic.common.object_wrapper import (transient_function_wrapper, - function_wrapper) -from testing_support.fixtures import catch_background_exceptions -def validate_log_events(events=None, forgone_attrs=None): - events = events or [{}] # Empty event allows assertions based on only forgone attrs to still run and validate +def validate_log_events(events=None, required_attrs=None, forgone_attrs=None): + events = events or [ + {} + ] # Empty event allows assertions based on only required or forgone attrs to still run and validate + required_attrs = required_attrs or [] forgone_attrs = forgone_attrs or [] @function_wrapper def _validate_wrapper(wrapped, instance, args, kwargs): - record_called = [] recorded_logs = [] @@ -44,12 +46,11 @@ def _validate_log_events(wrapped, instance, args, kwargs): return result - _new_wrapper = _validate_log_events(wrapped) val = _new_wrapper(*args, **kwargs) assert record_called logs = copy.copy(recorded_logs) - + record_called[:] = [] recorded_logs[:] = [] @@ -57,14 +58,13 @@ def _validate_log_events(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) @@ -79,12 +79,19 @@ 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 forgone_attrs: - if hasattr(captured, key): - mismatches.append("forgone_key: %s, value:<%s>" % (key, getattr(captured, key, None))) + for key in required_attrs: + if not hasattr(captured, key) and key not in captured.attributes: + mismatches.append("required_key: %s" % key) return False - elif key in captured.attributes: - mismatches.append("forgone_key: %s, value:<%s>" % (key, captured.attributes[key])) + + for key in forgone_attrs: + if hasattr(captured, key) or key in captured.attributes: + if hasattr(captured, key): + captured_value = getattr(captured, key, None) + elif key in captured.attributes: + captured_value = captured.attributes[key] + + mismatches.append("forgone_key: %s, value:<%s>" % (key, captured_value)) return False return True diff --git a/tests/testing_support/validators/validate_log_events_outside_transaction.py b/tests/testing_support/validators/validate_log_events_outside_transaction.py index 35c89a362..6c17d089b 100644 --- a/tests/testing_support/validators/validate_log_events_outside_transaction.py +++ b/tests/testing_support/validators/validate_log_events_outside_transaction.py @@ -20,13 +20,13 @@ 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 def _validate_wrapper(wrapped, instance, args, kwargs): - record_called = [] recorded_logs = [] @@ -55,14 +55,13 @@ 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,12 +76,19 @@ 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 forgone_attrs: - if hasattr(captured, key): - mismatches.append("forgone_key: %s, value:<%s>" % (key, getattr(captured, key, None))) + for key in required_attrs: + if not hasattr(captured, key) and key not in captured.attributes: + mismatches.append("required_key: %s" % key) return False - elif key in captured.attributes: - mismatches.append("forgone_key: %s, value:<%s>" % (key, captured.attributes[key])) + + for key in forgone_attrs: + if hasattr(captured, key) or key in captured.attributes: + if hasattr(captured, key): + captured_value = getattr(captured, key, None) + elif key in captured.attributes: + captured_value = captured.attributes[key] + + mismatches.append("forgone_key: %s, value:<%s>" % (key, captured_value)) return False return True From d98d5f2beac29e8602e68013c3be10409119f75e Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Thu, 4 Jan 2024 13:39:26 -0800 Subject: [PATCH 3/9] Squashed commit of the following: commit 3962f54d91bef1980523f40eb4649ef354634396 Author: Uma Annamalai Date: Thu Jan 4 12:50:58 2024 -0800 Remove case sensitive check in ASGIBrowserMiddleware check. (#1017) * Remove case sensitive check in should_insert_html. * [Mega-Linter] Apply linters fixes * Remove header decoding. --------- Co-authored-by: umaannamalai commit c3314aeac97b21615252f18c98384840a47db06f Author: Lalleh Rafeei <84813886+lrafeei@users.noreply.github.com> Date: Tue Jan 2 17:17:20 2024 -0800 Temporarily pin hypercorn version in tests (#1021) * Temporarily pin hypercorn to <0.16 * Temporarily pin hypercorn to <0.16 * Add comment to tox.ini --------- Co-authored-by: mergify[bot] <37929162+mergify[bot]@users.noreply.github.com> commit 13571451da8e48a8a2ea96d110e45b8e4ef537e3 Author: Uma Annamalai Date: Tue Jan 2 16:17:08 2024 -0800 Drop py27 from memcache testing. (#1018) commit 23f969fcfa9e1bf52e80766be0786152229cd43c Author: Timothy Pansino <11214426+TimPansino@users.noreply.github.com> Date: Wed Dec 20 17:01:50 2023 -0800 Nonced CSP Support (#998) * Add nonce to CSP in browser agent * Adjust nonce position * Add testing for browser timing nonces commit 8bfd2b788b222534639523f294577d724a3be5bb Author: Uma Annamalai Date: Mon Dec 18 13:58:10 2023 -0800 Remove RPM config workflow. (#1007) --- .github/actions/update-rpm-config/action.yml | 69 -------------------- .github/workflows/deploy-python.yml | 10 --- newrelic/api/asgi_application.py | 5 +- newrelic/api/transaction.py | 8 +-- newrelic/api/web_transaction.py | 20 ++++-- tests/agent_features/test_browser.py | 29 ++++++++ tox.ini | 5 +- 7 files changed, 52 insertions(+), 94 deletions(-) delete mode 100644 .github/actions/update-rpm-config/action.yml diff --git a/.github/actions/update-rpm-config/action.yml b/.github/actions/update-rpm-config/action.yml deleted file mode 100644 index 01a367c51..000000000 --- a/.github/actions/update-rpm-config/action.yml +++ /dev/null @@ -1,69 +0,0 @@ -name: "update-rpm-config" -description: "Set current version of agent in rpm config using API." -inputs: - agent-language: - description: "Language agent to configure (eg. python)" - required: true - default: "python" - agent-version: - description: "3-4 digit agent version number (eg. 1.2.3) with optional leading v (ignored)" - required: true - dry-run: - description: "Dry Run" - required: true - default: "false" - production-api-key: - description: "API key for New Relic Production" - required: false - -runs: - using: "composite" - steps: - - name: Trim potential leading v from agent version - shell: bash - run: | - AGENT_VERSION=${{ inputs.agent-version }} - echo "AGENT_VERSION=${AGENT_VERSION#"v"}" >> $GITHUB_ENV - - - name: Generate Payload - shell: bash - run: | - echo "PAYLOAD='{ \"system_configuration\": { \"key\": \"${{ inputs.agent-language }}_agent_version\", \"value\": \"${{ env.AGENT_VERSION }}\" } }'" >> $GITHUB_ENV - - - name: Generate Content-Type - shell: bash - run: | - echo "CONTENT_TYPE='Content-Type: application/json'" >> $GITHUB_ENV - - - name: Update system configuration page - shell: bash - if: ${{ inputs.dry-run == 'false' }} - run: | - curl -X POST 'https://api.newrelic.com/v2/system_configuration.json' \ - -H "X-Api-Key:${{ inputs.production-api-key }}" -i \ - -H ${{ env.CONTENT_TYPE }} \ - -d ${{ env.PAYLOAD }} - - - name: Verify system configuration update - shell: bash - if: ${{ inputs.dry-run == 'false' }} - run: | - PROD_VERSION=$(curl -X GET 'https://api.newrelic.com/v2/system_configuration.json' \ - -H "X-Api-Key:${{ inputs.production-api-key }}" \ - -H "${{ env.CONTENT_TYPE }}" | jq ".system_configurations | from_entries | .${{inputs.agent-language}}_agent_version") - - if [ "${{ env.AGENT_VERSION }}" != "$PROD_VERSION" ]; then - echo "Version mismatch: $PROD_VERSION" - exit 1 - fi - - - name: (dry-run) Update system configuration page - shell: bash - if: ${{ inputs.dry-run != 'false' }} - run: | - cat << EOF - curl -X POST 'https://api.newrelic.com/v2/system_configuration.json' \ - -H "X-Api-Key:**REDACTED**" -i \ - -H ${{ env.CONTENT_TYPE }} \ - -d ${{ env.PAYLOAD }} - EOF diff --git a/.github/workflows/deploy-python.yml b/.github/workflows/deploy-python.yml index 6ad06398f..fe16ee485 100644 --- a/.github/workflows/deploy-python.yml +++ b/.github/workflows/deploy-python.yml @@ -80,13 +80,3 @@ jobs: env: TWINE_USERNAME: __token__ TWINE_PASSWORD: ${{ secrets.PYPI_TOKEN }} - - - name: Update RPM Config - uses: ./.github/actions/update-rpm-config - with: - agent-language: "python" - target-system: "all" - agent-version: "${{ github.ref_name }}" - dry-run: "false" - production-api-key: ${{ secrets.NEW_RELIC_API_KEY_PRODUCTION }} - staging-api-key: ${{ secrets.NEW_RELIC_API_KEY_STAGING }} diff --git a/newrelic/api/asgi_application.py b/newrelic/api/asgi_application.py index 2e4e4979b..201e8643e 100644 --- a/newrelic/api/asgi_application.py +++ b/newrelic/api/asgi_application.py @@ -97,7 +97,9 @@ def should_insert_html(self, headers): content_type = None for header_name, header_value in headers: - # assume header names are lower cased in accordance with ASGI spec + # ASGI spec (https://asgi.readthedocs.io/en/latest/specs/www.html#http) states + # header names should be lower cased, but not required + header_name = header_name.lower() if header_name == b"content-type": content_type = header_value elif header_name == b"content-encoding": @@ -318,7 +320,6 @@ async def nr_async_asgi(receive, send): send=send, source=wrapped, ) as transaction: - # Record details of framework against the transaction for later # reporting as supportability metrics. if framework: diff --git a/newrelic/api/transaction.py b/newrelic/api/transaction.py index 26b6bfa4a..67f1bab34 100644 --- a/newrelic/api/transaction.py +++ b/newrelic/api/transaction.py @@ -1912,17 +1912,17 @@ def add_framework_info(name, version=None): transaction.add_framework_info(name, version) -def get_browser_timing_header(): +def get_browser_timing_header(nonce=None): transaction = current_transaction() if transaction and hasattr(transaction, "browser_timing_header"): - return transaction.browser_timing_header() + return transaction.browser_timing_header(nonce) return "" -def get_browser_timing_footer(): +def get_browser_timing_footer(nonce=None): transaction = current_transaction() if transaction and hasattr(transaction, "browser_timing_footer"): - return transaction.browser_timing_footer() + return transaction.browser_timing_footer(nonce) return "" diff --git a/newrelic/api/web_transaction.py b/newrelic/api/web_transaction.py index 47155425e..d74f1d6d3 100644 --- a/newrelic/api/web_transaction.py +++ b/newrelic/api/web_transaction.py @@ -39,9 +39,8 @@ _logger = logging.getLogger(__name__) -_js_agent_header_fragment = '' -_js_agent_footer_fragment = '' +_js_agent_header_fragment = '' +_js_agent_footer_fragment = '' # Seconds since epoch for Jan 1 2000 JAN_1_2000 = time.mktime((2000, 1, 1, 0, 0, 0, 0, 0, 0)) @@ -156,6 +155,13 @@ def _is_websocket(environ): return environ.get('HTTP_UPGRADE', '').lower() == 'websocket' +def _encode_nonce(nonce): + if not nonce: + return "" + else: + return ' nonce="%s"' % ensure_str(nonce) # Extra space intentional + + class WebTransaction(Transaction): unicode_error_reported = False QUEUE_TIME_HEADERS = ('x-request-start', 'x-queue-start') @@ -386,7 +392,7 @@ def _update_agent_attributes(self): return super(WebTransaction, self)._update_agent_attributes() - def browser_timing_header(self): + def browser_timing_header(self, nonce=None): """Returns the JavaScript header to be included in any HTML response to perform real user monitoring. This function returns the header as a native Python string. In Python 2 native strings @@ -437,7 +443,7 @@ def browser_timing_header(self): # 'none'. if self._settings.js_agent_loader: - header = _js_agent_header_fragment % self._settings.js_agent_loader + header = _js_agent_header_fragment % (_encode_nonce(nonce), self._settings.js_agent_loader) # To avoid any issues with browser encodings, we will make sure # that the javascript we inject for the browser agent is ASCII @@ -476,7 +482,7 @@ def browser_timing_header(self): return header - def browser_timing_footer(self): + def browser_timing_footer(self, nonce=None): """Returns the JavaScript footer to be included in any HTML response to perform real user monitoring. This function returns the footer as a native Python string. In Python 2 native strings @@ -541,7 +547,7 @@ def browser_timing_footer(self): attributes = obfuscate(json_encode(attributes), obfuscation_key) footer_data['atts'] = attributes - footer = _js_agent_footer_fragment % json_encode(footer_data) + footer = _js_agent_footer_fragment % (_encode_nonce(nonce), json_encode(footer_data)) # To avoid any issues with browser encodings, we will make sure that # the javascript we inject for the browser agent is ASCII encodable. diff --git a/tests/agent_features/test_browser.py b/tests/agent_features/test_browser.py index e0f562d1e..735cec5c1 100644 --- a/tests/agent_features/test_browser.py +++ b/tests/agent_features/test_browser.py @@ -32,6 +32,7 @@ get_browser_timing_footer, get_browser_timing_header, ) +from newrelic.api.web_transaction import web_transaction from newrelic.api.wsgi_application import wsgi_application from newrelic.common.encoding_utils import deobfuscate @@ -1026,3 +1027,31 @@ def test_html_insertion_manual_rum_insertion(): # footer added by the agent. response.mustcontain(no=["NREUM HEADER", "NREUM.info"]) + + +_test_get_browser_timing_nonces_settings = { + "browser_monitoring.enabled": True, + "browser_monitoring.auto_instrument": False, + "js_agent_loader": "", +} + +@override_application_settings(_test_get_browser_timing_nonces_settings) +@web_transaction(scheme="http", host="127.0.0.1", port=80, request_method="GET", + request_path="/", query_string=None, headers={}) +def test_get_browser_timing_nonces(): + header = get_browser_timing_header("NONCE") + footer = get_browser_timing_footer("NONCE") + + assert header == '' + assert '' + assert '