From 4d9c35770bdf2082cafb76b4a243c42bba9ab078 Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Thu, 7 Dec 2023 14:21:49 -0800 Subject: [PATCH 01/19] Add tests for logging's json logging --- tests/logger_logging/test_json_logging.py | 82 +++++++++++++++++++++++ 1 file changed, 82 insertions(+) create mode 100644 tests/logger_logging/test_json_logging.py diff --git a/tests/logger_logging/test_json_logging.py b/tests/logger_logging/test_json_logging.py new file mode 100644 index 000000000..d7e29282c --- /dev/null +++ b/tests/logger_logging/test_json_logging.py @@ -0,0 +1,82 @@ +# 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 newrelic.api.time_trace import current_trace +from newrelic.api.transaction import current_transaction +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 + + +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): + set_trace_ids() + + logger.error({"message": "A", "my_attr": 3}) + + assert len(logger.caplog.records) == 1 + + +def update_all(events, attrs): + for event in events: + event.update(attrs) + + +_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"} +_common_attributes_trace_linking.update(_common_attributes_service_linking) + +_test_json_logging_inside_transaction_events = [ + {"message": "A", "level": "ERROR"}, +] +update_all(_test_json_logging_inside_transaction_events, _common_attributes_trace_linking) + + +def test_json_logging_inside_transaction(logger): + @validate_log_events(_test_json_logging_inside_transaction_events) + @validate_log_event_count(1) + @background_task() + def test(): + exercise_logging(logger) + + test() + + +# _test_json_logging_outside_transaction_events = [ +# {"message": "C", "level": "WARNING"}, +# {"message": "D", "level": "ERROR"}, +# {"message": "E", "level": "CRITICAL"}, +# ] +# update_all(_test_json_logging_outside_transaction_events, _common_attributes_service_linking) + + +# @reset_core_stats_engine() +# def test_json_logging_outside_transaction(logger): +# @validate_log_events_outside_transaction(_test_json_logging_outside_transaction_events) +# @validate_log_event_count_outside_transaction(3) +# def test(): +# exercise_logging(logger) + +# test() From a7d4208676d615c49b742be40fe1e7d40b0e82da Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Mon, 11 Dec 2023 11:53:05 -0800 Subject: [PATCH 02/19] Upgrade record_log_event to handle dict logging --- newrelic/api/transaction.py | 14 ++++++++++++-- newrelic/core/stats_engine.py | 14 ++++++++++++-- 2 files changed, 24 insertions(+), 4 deletions(-) diff --git a/newrelic/api/transaction.py b/newrelic/api/transaction.py index 26b6bfa4a..7a9c2b7d1 100644 --- a/newrelic/api/transaction.py +++ b/newrelic/api/transaction.py @@ -1540,11 +1540,21 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=None, timestamp = timestamp if timestamp is not None else time.time() level = str(level) if level is not None else "UNKNOWN" - if not message or message.isspace(): + is_string = isinstance(message, six.string_types) + is_hashmap = isinstance(message, dict) + + if not is_string and not is_hashmap: + _logger.debug("record_log_event called where message was not a string type or dictionary. No log event will be sent.") + return + + if not message or is_string and message.isspace(): _logger.debug("record_log_event called where message was missing. No log event will be sent.") return - message = truncate(message, MAX_LOG_MESSAGE_LENGTH) + if is_string: + message = truncate(message, MAX_LOG_MESSAGE_LENGTH) + else: + message = message collected_attributes = get_linking_metadata() if attributes and (settings and settings.application_logging.forwarding.context_data.enabled): diff --git a/newrelic/core/stats_engine.py b/newrelic/core/stats_engine.py index e09637ee9..71e184587 100644 --- a/newrelic/core/stats_engine.py +++ b/newrelic/core/stats_engine.py @@ -1233,11 +1233,21 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=None, timestamp = timestamp if timestamp is not None else time.time() level = str(level) if level is not None else "UNKNOWN" - if not message or message.isspace(): + is_string = isinstance(message, six.string_types) + is_hashmap = isinstance(message, dict) + + if not is_string and not is_hashmap: + _logger.debug("record_log_event called where message was not a string type or dictionary. No log event will be sent.") + return + + if not message or is_string and message.isspace(): _logger.debug("record_log_event called where message was missing. No log event will be sent.") return - message = truncate(message, MAX_LOG_MESSAGE_LENGTH) + if is_string: + message = truncate(message, MAX_LOG_MESSAGE_LENGTH) + else: + message = message collected_attributes = get_linking_metadata() if attributes and (settings and settings.application_logging.forwarding.context_data.enabled): From e9c2753b9316e9134ebe6258e2a5ac12c627efd9 Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Mon, 11 Dec 2023 12:09:28 -0800 Subject: [PATCH 03/19] Update logging to capture dict messages --- newrelic/hooks/logger_logging.py | 5 +++- tests/logger_logging/test_json_logging.py | 28 +++++++++++------------ 2 files changed, 17 insertions(+), 16 deletions(-) diff --git a/newrelic/hooks/logger_logging.py b/newrelic/hooks/logger_logging.py index 80cf0fd24..7de67a3c8 100644 --- a/newrelic/hooks/logger_logging.py +++ b/newrelic/hooks/logger_logging.py @@ -89,7 +89,10 @@ def wrap_callHandlers(wrapped, instance, args, kwargs): if settings.application_logging.forwarding and settings.application_logging.forwarding.enabled: try: - message = record.getMessage() + message = record.msg + if isinstance(message, dict): + # Allow python to convert the message to a string and template it with args. + message = record.getMessage() attrs = filter_record_attributes(record) record_log_event( message=message, level=level_name, timestamp=int(record.created * 1000), attributes=attrs diff --git a/tests/logger_logging/test_json_logging.py b/tests/logger_logging/test_json_logging.py index d7e29282c..65c78b26c 100644 --- a/tests/logger_logging/test_json_logging.py +++ b/tests/logger_logging/test_json_logging.py @@ -34,7 +34,7 @@ def set_trace_ids(): def exercise_logging(logger): set_trace_ids() - logger.error({"message": "A", "my_attr": 3}) + logger.error({"message": "A", "other_attr": 2}) assert len(logger.caplog.records) == 1 @@ -49,7 +49,7 @@ def update_all(events, attrs): _common_attributes_trace_linking.update(_common_attributes_service_linking) _test_json_logging_inside_transaction_events = [ - {"message": "A", "level": "ERROR"}, + {"message": {"message": "A", "other_attr": 2}, "level": "ERROR"}, ] update_all(_test_json_logging_inside_transaction_events, _common_attributes_trace_linking) @@ -64,19 +64,17 @@ def test(): test() -# _test_json_logging_outside_transaction_events = [ -# {"message": "C", "level": "WARNING"}, -# {"message": "D", "level": "ERROR"}, -# {"message": "E", "level": "CRITICAL"}, -# ] -# update_all(_test_json_logging_outside_transaction_events, _common_attributes_service_linking) +_test_json_logging_outside_transaction_events = [ + {"message": {"message": "A", "other_attr": 2}, "level": "ERROR"}, +] +update_all(_test_json_logging_outside_transaction_events, _common_attributes_service_linking) -# @reset_core_stats_engine() -# def test_json_logging_outside_transaction(logger): -# @validate_log_events_outside_transaction(_test_json_logging_outside_transaction_events) -# @validate_log_event_count_outside_transaction(3) -# def test(): -# exercise_logging(logger) +@reset_core_stats_engine() +def test_json_logging_outside_transaction(logger): + @validate_log_events_outside_transaction(_test_json_logging_outside_transaction_events) + @validate_log_event_count_outside_transaction(1) + def test(): + exercise_logging(logger) -# test() + test() From 808811af92939ebe5753e205638e6d54ebda9200 Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Wed, 20 Dec 2023 15:24:14 -0800 Subject: [PATCH 04/19] Add attributes for dict log messages --- newrelic/api/transaction.py | 11 +++++++---- newrelic/core/stats_engine.py | 11 +++++++---- 2 files changed, 14 insertions(+), 8 deletions(-) diff --git a/newrelic/api/transaction.py b/newrelic/api/transaction.py index 7a9c2b7d1..38258b9da 100644 --- a/newrelic/api/transaction.py +++ b/newrelic/api/transaction.py @@ -1547,14 +1547,12 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=None, _logger.debug("record_log_event called where message was not a string type or dictionary. No log event will be sent.") return - if not message or is_string and message.isspace(): - _logger.debug("record_log_event called where message was missing. No log event will be sent.") + if not attributes and not message or is_string and message.isspace(): + _logger.debug("record_log_event called where message was missing, and no attributes found. No log event will be sent.") return if is_string: message = truncate(message, MAX_LOG_MESSAGE_LENGTH) - else: - message = message collected_attributes = get_linking_metadata() if attributes and (settings and settings.application_logging.forwarding.context_data.enabled): @@ -1562,6 +1560,11 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=None, if context_attributes: collected_attributes.update(context_attributes) + if is_hashmap: + message_attributes = resolve_logging_context_attributes(message, settings.attribute_filter, "message.") + if message_attributes: + collected_attributes.update(message_attributes) + event = LogEventNode( timestamp=timestamp, level=level, diff --git a/newrelic/core/stats_engine.py b/newrelic/core/stats_engine.py index 71e184587..633b11854 100644 --- a/newrelic/core/stats_engine.py +++ b/newrelic/core/stats_engine.py @@ -1240,14 +1240,12 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=None, _logger.debug("record_log_event called where message was not a string type or dictionary. No log event will be sent.") return - if not message or is_string and message.isspace(): - _logger.debug("record_log_event called where message was missing. No log event will be sent.") + if not attributes and not message or is_string and message.isspace(): + _logger.debug("record_log_event called where message was missing, and no attributes found. No log event will be sent.") return if is_string: message = truncate(message, MAX_LOG_MESSAGE_LENGTH) - else: - message = message collected_attributes = get_linking_metadata() if attributes and (settings and settings.application_logging.forwarding.context_data.enabled): @@ -1255,6 +1253,11 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=None, if context_attributes: collected_attributes.update(context_attributes) + if is_hashmap: + message_attributes = resolve_logging_context_attributes(message, settings.attribute_filter, "message.") + if message_attributes: + collected_attributes.update(message_attributes) + event = LogEventNode( timestamp=timestamp, level=level, From 42d4aa44304e248f17568171bfbb9c0f9a864cfd Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Wed, 20 Dec 2023 17:05:59 -0800 Subject: [PATCH 05/19] Implementation of JSON message filtering --- newrelic/api/transaction.py | 45 +++++-- newrelic/core/application.py | 13 +- newrelic/core/stats_engine.py | 45 +++++-- newrelic/hooks/logger_logging.py | 4 +- tests/agent_features/test_log_events.py | 136 +++++++++++++------- tests/logger_logging/test_log_forwarding.py | 11 +- 6 files changed, 174 insertions(+), 80 deletions(-) diff --git a/newrelic/api/transaction.py b/newrelic/api/transaction.py index 38258b9da..dec9ca887 100644 --- a/newrelic/api/transaction.py +++ b/newrelic/api/transaction.py @@ -1540,31 +1540,50 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=None, timestamp = timestamp if timestamp is not None else time.time() level = str(level) if level is not None else "UNKNOWN" - is_string = isinstance(message, six.string_types) - is_hashmap = isinstance(message, dict) + # Unpack message and attributes from dict inputs + if isinstance(message, dict): + message_attributes = {k: v for k, v in message.items() if k != "message"} + message = str(message.get("message", "")) + else: + message_attributes = None - if not is_string and not is_hashmap: - _logger.debug("record_log_event called where message was not a string type or dictionary. No log event will be sent.") + # Exit early for invalid message type after unpacking + is_string = isinstance(message, six.string_types) + if message is not None and not is_string: + _logger.debug("record_log_event called where message was not found. No log event will be sent.") return - if not attributes and not message or is_string and message.isspace(): + # Exit early if no message or attributes found + no_message = not message or message.isspace() + if not attributes and no_message: _logger.debug("record_log_event called where message was missing, and no attributes found. No log event will be sent.") return - if is_string: + # Truncate the now unpacked and string converted message + if is_string: message = truncate(message, MAX_LOG_MESSAGE_LENGTH) - collected_attributes = get_linking_metadata() - if attributes and (settings and settings.application_logging.forwarding.context_data.enabled): - context_attributes = resolve_logging_context_attributes(attributes, settings.attribute_filter, "context.") - if context_attributes: - collected_attributes.update(context_attributes) + # Collect attributes from linking metadata, context data, and message attributes + collected_attributes = {} + if settings and settings.application_logging.forwarding.context_data.enabled: + if attributes: + context_attributes = resolve_logging_context_attributes(attributes, settings.attribute_filter, "context.") + if context_attributes: + collected_attributes.update(context_attributes) - if is_hashmap: - message_attributes = resolve_logging_context_attributes(message, settings.attribute_filter, "message.") + if message_attributes: + message_attributes = resolve_logging_context_attributes(message_attributes, settings.attribute_filter, "message.") if message_attributes: collected_attributes.update(message_attributes) + # Exit early if no message or attributes found after filtering + if not collected_attributes and no_message: + _logger.debug("record_log_event called where message was missing, and no attributes found. No log event will be sent.") + return + + # Finally, add in linking attributes after checking that there is a valid message or at least 1 attribute + collected_attributes.update(get_linking_metadata()) + event = LogEventNode( timestamp=timestamp, level=level, diff --git a/newrelic/core/application.py b/newrelic/core/application.py index b7f6fb27d..42cff443e 100644 --- a/newrelic/core/application.py +++ b/newrelic/core/application.py @@ -943,13 +943,12 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=None, if not self._active_session: return - if message: - with self._stats_custom_lock: - event = self._stats_engine.record_log_event( - message, level, timestamp, attributes=attributes, priority=priority - ) - if event: - self._global_events_account += 1 + with self._stats_custom_lock: + event = self._stats_engine.record_log_event( + message, level, timestamp, attributes=attributes, priority=priority + ) + if event: + self._global_events_account += 1 def record_transaction(self, data): """Record a single transaction against this application.""" diff --git a/newrelic/core/stats_engine.py b/newrelic/core/stats_engine.py index 633b11854..afd27c13d 100644 --- a/newrelic/core/stats_engine.py +++ b/newrelic/core/stats_engine.py @@ -1233,31 +1233,50 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=None, timestamp = timestamp if timestamp is not None else time.time() level = str(level) if level is not None else "UNKNOWN" - is_string = isinstance(message, six.string_types) - is_hashmap = isinstance(message, dict) + # Unpack message and attributes from dict inputs + if isinstance(message, dict): + message_attributes = {k: v for k, v in message.items() if k != "message"} + message = str(message.get("message", "")) + else: + message_attributes = None - if not is_string and not is_hashmap: - _logger.debug("record_log_event called where message was not a string type or dictionary. No log event will be sent.") + # Exit early for invalid message type after unpacking + is_string = isinstance(message, six.string_types) + if message is not None and not is_string: + _logger.debug("record_log_event called where message was not found. No log event will be sent.") return - if not attributes and not message or is_string and message.isspace(): + # Exit early if no message or attributes found + no_message = not message or message.isspace() + if not attributes and no_message: _logger.debug("record_log_event called where message was missing, and no attributes found. No log event will be sent.") return - if is_string: + # Truncate the now unpacked and string converted message + if is_string: message = truncate(message, MAX_LOG_MESSAGE_LENGTH) - collected_attributes = get_linking_metadata() - if attributes and (settings and settings.application_logging.forwarding.context_data.enabled): - context_attributes = resolve_logging_context_attributes(attributes, settings.attribute_filter, "context.") - if context_attributes: - collected_attributes.update(context_attributes) + # Collect attributes from linking metadata, context data, and message attributes + collected_attributes = {} + if settings and settings.application_logging.forwarding.context_data.enabled: + if attributes: + context_attributes = resolve_logging_context_attributes(attributes, settings.attribute_filter, "context.") + if context_attributes: + collected_attributes.update(context_attributes) - if is_hashmap: - message_attributes = resolve_logging_context_attributes(message, settings.attribute_filter, "message.") + if message_attributes: + message_attributes = resolve_logging_context_attributes(message_attributes, settings.attribute_filter, "message.") if message_attributes: collected_attributes.update(message_attributes) + # Exit early if no message or attributes found after filtering + if not collected_attributes and no_message: + _logger.debug("record_log_event called where message was missing, and no attributes found. No log event will be sent.") + return + + # Finally, add in linking attributes after checking that there is a valid message or at least 1 attribute + collected_attributes.update(get_linking_metadata()) + event = LogEventNode( timestamp=timestamp, level=level, diff --git a/newrelic/hooks/logger_logging.py b/newrelic/hooks/logger_logging.py index 7de67a3c8..8f1ebcacc 100644 --- a/newrelic/hooks/logger_logging.py +++ b/newrelic/hooks/logger_logging.py @@ -93,9 +93,9 @@ def wrap_callHandlers(wrapped, instance, args, kwargs): if isinstance(message, dict): # Allow python to convert the message to a string and template it with args. message = record.getMessage() - attrs = filter_record_attributes(record) + context_attrs = filter_record_attributes(record) record_log_event( - message=message, level=level_name, timestamp=int(record.created * 1000), attributes=attrs + message=message, level=level_name, timestamp=int(record.created * 1000), attributes=context_attrs ) except Exception: pass diff --git a/tests/agent_features/test_log_events.py b/tests/agent_features/test_log_events.py index 91585d2ff..8a89b6e40 100644 --- a/tests/agent_features/test_log_events.py +++ b/tests/agent_features/test_log_events.py @@ -72,16 +72,19 @@ def exercise_record_log_event(): 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) + record_log_event(None, attributes={"attributes_only": "value"}) + record_log_event({"message": "dict_message"}) # Unsent due to message content missing record_log_event("") record_log_event(" ") + record_log_event({"message": ""}) + record_log_event({"filtered_attribute": "should_be_removed"}) record_log_event(None) - record_log_event(None, attributes={"attributes_only": "value"}) enable_log_forwarding = override_application_settings( - {"application_logging.forwarding.enabled": True, "application_logging.forwarding.context_data.enabled": True} + {"application_logging.forwarding.enabled": True, "application_logging.forwarding.context_data.enabled": True, "application_logging.forwarding.context_data.exclude": "filtered_attribute"} ) disable_log_forwarding = override_application_settings({"application_logging.forwarding.enabled": False}) @@ -123,6 +126,8 @@ def exercise_record_log_event(): "context.non_serializable_attr": "", "context.attr_value_too_long": "*" * 255, }, + {"context.attributes_only": "value"}, + {"message": "dict_message"}, ] _exercise_record_log_event_inside_transaction_events = [ combine_dicts(_common_attributes_trace_linking, log) for log in _exercise_record_log_event_events @@ -252,41 +257,37 @@ def test(): 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), +_test_record_log_event_context_attribute_filtering_params = [ + ("", "", "A", True), + ("", "A", "A", False), + ("", "A", "B", True), + ("A B", "*", "A", True), + ("A B", "*", "B", True), + ("A B", "*", "C", False), + ("A B", "C", "A", True), + ("A B", "C", "C", False), + ("A B", "B", "A", True), + ("A B", "B", "B", False), + ("A", "A *", "A", False), + ("A", "A *", "B", False), + ("A*", "", "A", True), + ("A*", "", "AB", True), + ("", "A*", "A", False), + ("", "A*", "B", True), + ("A*", "AB", "AC", True), + ("A*", "AB", "AB", False), + ("AB", "A*", "AB", True), + ("A*", "AB*", "ACB", True), + ("A*", "AB*", "ABC", False), ] - -@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): +@pytest.mark.parametrize("prefix", ("context", "message")) +@pytest.mark.parametrize("include,exclude,attr,expected", _test_record_log_event_context_attribute_filtering_params) +def test_record_log_event_context_attribute_filtering_inside_transaction(include, exclude, attr, expected, prefix): if expected: - expected_event = {"required_attrs": [attr]} + expected_event = {"required_attrs": [".".join((prefix, attr))]} else: - expected_event = {"forgone_attrs": [attr]} + expected_event = {"forgone_attrs": [".".join((prefix, attr))]} @override_application_settings( { @@ -300,21 +301,22 @@ def test_record_log_event_attribute_filtering_inside_transaction(include, exclud @validate_log_event_count(1) @background_task() def test(): - if attr.startswith("context."): - record_log_event("A", attributes={attr.lstrip("context."): 1}) + if prefix == "context": + record_log_event("A", attributes={attr: 1}) else: - record_log_event("A") + record_log_event({"message": "A", attr: 1}) test() -@pytest.mark.parametrize("include,exclude,attr,expected", _test_record_log_event_attribute_filtering_params) +@pytest.mark.parametrize("prefix", ("context", "message")) +@pytest.mark.parametrize("include,exclude,attr,expected", _test_record_log_event_context_attribute_filtering_params) @reset_core_stats_engine() -def test_record_log_event_attribute_filtering_outside_transaction(include, exclude, attr, expected): +def test_record_log_event_context_attribute_filtering_outside_transaction(include, exclude, attr, expected, prefix): if expected: - expected_event = {"required_attrs": [attr]} + expected_event = {"required_attrs": [".".join((prefix, attr))]} else: - expected_event = {"forgone_attrs": [attr]} + expected_event = {"forgone_attrs": [".".join((prefix, attr))]} @override_application_settings( { @@ -327,9 +329,57 @@ def test_record_log_event_attribute_filtering_outside_transaction(include, exclu @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}) + if prefix == "context": + record_log_event("A", attributes={attr: 1}) else: - record_log_event("A") + record_log_event({"message": "A", attr: 1}) + + test() + + +_test_record_log_event_linking_attribute_no_filtering_params = [ + ("", ""), + ("", "entity.name"), + ("", "*"), +] + +@pytest.mark.parametrize("include,exclude", _test_record_log_event_linking_attribute_no_filtering_params) +def test_record_log_event_linking_attribute_no_filtering_inside_transaction(include, exclude): + attr = "entity.name" + + @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(required_attrs=[attr]) + @validate_log_event_count(1) + @background_task() + def test(): + record_log_event("A") + + test() + + +@pytest.mark.parametrize("include,exclude", _test_record_log_event_linking_attribute_no_filtering_params) +@reset_core_stats_engine() +def test_record_log_event_linking_attribute_filtering_outside_transaction(include, exclude): + attr = "entity.name" + + @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(required_attrs=[attr]) + @validate_log_event_count_outside_transaction(1) + def test(): + record_log_event("A") test() diff --git a/tests/logger_logging/test_log_forwarding.py b/tests/logger_logging/test_log_forwarding.py index ee6c689b7..c622fef00 100644 --- a/tests/logger_logging/test_log_forwarding.py +++ b/tests/logger_logging/test_log_forwarding.py @@ -40,6 +40,9 @@ def exercise_logging(logger): logger.warning("C") logger.error("D") logger.critical("E") + + logger.error({"message": "F", "attr": 1}) + logger.warning({"attr": "G"}) assert len(logger.caplog.records) == 3 @@ -56,13 +59,15 @@ def update_all(events, attrs): {"message": "C", "level": "WARNING"}, {"message": "D", "level": "ERROR"}, {"message": "E", "level": "CRITICAL"}, + {"message": "F", "level": "ERROR", "message.attr": 1}, + {"message.attr": "G", "level": "WARNING"}, ] update_all(_test_logging_inside_transaction_events, _common_attributes_trace_linking) def test_logging_inside_transaction(logger): @validate_log_events(_test_logging_inside_transaction_events) - @validate_log_event_count(3) + @validate_log_event_count(5) @background_task() def test(): exercise_logging(logger) @@ -74,6 +79,8 @@ def test(): {"message": "C", "level": "WARNING"}, {"message": "D", "level": "ERROR"}, {"message": "E", "level": "CRITICAL"}, + {"message": "F", "level": "ERROR", "message.attr": 1}, + {"message.attr": "G", "level": "WARNING"}, ] update_all(_test_logging_outside_transaction_events, _common_attributes_service_linking) @@ -81,7 +88,7 @@ def test(): @reset_core_stats_engine() def test_logging_outside_transaction(logger): @validate_log_events_outside_transaction(_test_logging_outside_transaction_events) - @validate_log_event_count_outside_transaction(3) + @validate_log_event_count_outside_transaction(5) def test(): exercise_logging(logger) From 8faf043dca2a56395ebed11a9592ba4604697a44 Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Thu, 21 Dec 2023 16:29:59 -0800 Subject: [PATCH 06/19] Correct attributes only log behavior --- newrelic/api/transaction.py | 2 +- newrelic/core/stats_engine.py | 2 +- tests/agent_features/test_log_events.py | 4 +++- 3 files changed, 5 insertions(+), 3 deletions(-) diff --git a/newrelic/api/transaction.py b/newrelic/api/transaction.py index dec9ca887..fa6794cc2 100644 --- a/newrelic/api/transaction.py +++ b/newrelic/api/transaction.py @@ -1555,7 +1555,7 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=None, # Exit early if no message or attributes found no_message = not message or message.isspace() - if not attributes and no_message: + if not attributes and not message_attributes and no_message: _logger.debug("record_log_event called where message was missing, and no attributes found. No log event will be sent.") return diff --git a/newrelic/core/stats_engine.py b/newrelic/core/stats_engine.py index afd27c13d..3dc682731 100644 --- a/newrelic/core/stats_engine.py +++ b/newrelic/core/stats_engine.py @@ -1248,7 +1248,7 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=None, # Exit early if no message or attributes found no_message = not message or message.isspace() - if not attributes and no_message: + if not attributes and not message_attributes and no_message: _logger.debug("record_log_event called where message was missing, and no attributes found. No log event will be sent.") return diff --git a/tests/agent_features/test_log_events.py b/tests/agent_features/test_log_events.py index 8a89b6e40..42be365c1 100644 --- a/tests/agent_features/test_log_events.py +++ b/tests/agent_features/test_log_events.py @@ -73,6 +73,7 @@ def exercise_record_log_event(): record_log_event("positional_arguments", "WARNING", 2345, {"key": "value"}) record_log_event("serialized_attributes", attributes=_serialized_attributes) record_log_event(None, attributes={"attributes_only": "value"}) + record_log_event({"attributes_only": "value"}) record_log_event({"message": "dict_message"}) # Unsent due to message content missing @@ -84,7 +85,7 @@ def exercise_record_log_event(): enable_log_forwarding = override_application_settings( - {"application_logging.forwarding.enabled": True, "application_logging.forwarding.context_data.enabled": True, "application_logging.forwarding.context_data.exclude": "filtered_attribute"} + {"application_logging.forwarding.enabled": True, "application_logging.forwarding.context_data.enabled": True, "application_logging.forwarding.context_data.exclude": ["filtered_attribute"]} ) disable_log_forwarding = override_application_settings({"application_logging.forwarding.enabled": False}) @@ -127,6 +128,7 @@ def exercise_record_log_event(): "context.attr_value_too_long": "*" * 255, }, {"context.attributes_only": "value"}, + {"message.attributes_only": "value"}, {"message": "dict_message"}, ] _exercise_record_log_event_inside_transaction_events = [ From 079120686a077ec95df501afb9db4c0eb4d3bbe7 Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Thu, 21 Dec 2023 17:23:16 -0800 Subject: [PATCH 07/19] Testing for logging attributes --- newrelic/hooks/logger_logging.py | 17 ++-- tests/logger_logging/conftest.py | 1 + tests/logger_logging/test_json_logging.py | 80 ------------------- tests/logger_logging/test_local_decorating.py | 15 +++- tests/logger_logging/test_log_forwarding.py | 77 ++++++++++++++---- 5 files changed, 80 insertions(+), 110 deletions(-) delete mode 100644 tests/logger_logging/test_json_logging.py diff --git a/newrelic/hooks/logger_logging.py b/newrelic/hooks/logger_logging.py index 8f1ebcacc..a745b238e 100644 --- a/newrelic/hooks/logger_logging.py +++ b/newrelic/hooks/logger_logging.py @@ -27,7 +27,7 @@ from urllib.parse import quote -DEFAULT_LOG_RECORD_KEYS = frozenset(set(vars(LogRecord("", 0, "", 0, "", (), None))) | {"message"}) +IGNORED_LOG_RECORD_KEYS = set(["message", "msg"]) def add_nr_linking_metadata(message): @@ -52,15 +52,6 @@ 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) @@ -93,7 +84,11 @@ def wrap_callHandlers(wrapped, instance, args, kwargs): if isinstance(message, dict): # Allow python to convert the message to a string and template it with args. message = record.getMessage() - context_attrs = filter_record_attributes(record) + + # Grab and filter context attributes from log record + record_attrs = vars(record) + context_attrs = {k: record_attrs[k] for k in vars(record) if k not in IGNORED_LOG_RECORD_KEYS} + record_log_event( message=message, level=level_name, timestamp=int(record.created * 1000), attributes=context_attrs ) diff --git a/tests/logger_logging/conftest.py b/tests/logger_logging/conftest.py index 46e8f4ec3..b9ecf8526 100644 --- a/tests/logger_logging/conftest.py +++ b/tests/logger_logging/conftest.py @@ -26,6 +26,7 @@ "debug.record_transaction_failure": True, "application_logging.enabled": True, "application_logging.forwarding.enabled": True, + "application_logging.forwarding.context_data.enabled": True, "application_logging.metrics.enabled": True, "application_logging.local_decorating.enabled": True, "event_harvest_config.harvest_limits.log_event_data": 100000, diff --git a/tests/logger_logging/test_json_logging.py b/tests/logger_logging/test_json_logging.py deleted file mode 100644 index 65c78b26c..000000000 --- a/tests/logger_logging/test_json_logging.py +++ /dev/null @@ -1,80 +0,0 @@ -# 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 newrelic.api.time_trace import current_trace -from newrelic.api.transaction import current_transaction -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 - - -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): - set_trace_ids() - - logger.error({"message": "A", "other_attr": 2}) - - assert len(logger.caplog.records) == 1 - - -def update_all(events, attrs): - for event in events: - event.update(attrs) - - -_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"} -_common_attributes_trace_linking.update(_common_attributes_service_linking) - -_test_json_logging_inside_transaction_events = [ - {"message": {"message": "A", "other_attr": 2}, "level": "ERROR"}, -] -update_all(_test_json_logging_inside_transaction_events, _common_attributes_trace_linking) - - -def test_json_logging_inside_transaction(logger): - @validate_log_events(_test_json_logging_inside_transaction_events) - @validate_log_event_count(1) - @background_task() - def test(): - exercise_logging(logger) - - test() - - -_test_json_logging_outside_transaction_events = [ - {"message": {"message": "A", "other_attr": 2}, "level": "ERROR"}, -] -update_all(_test_json_logging_outside_transaction_events, _common_attributes_service_linking) - - -@reset_core_stats_engine() -def test_json_logging_outside_transaction(logger): - @validate_log_events_outside_transaction(_test_json_logging_outside_transaction_events) - @validate_log_event_count_outside_transaction(1) - def test(): - exercise_logging(logger) - - test() diff --git a/tests/logger_logging/test_local_decorating.py b/tests/logger_logging/test_local_decorating.py index d4917eff5..7b420375c 100644 --- a/tests/logger_logging/test_local_decorating.py +++ b/tests/logger_logging/test_local_decorating.py @@ -35,10 +35,10 @@ def set_trace_ids(): trace.guid = "abcdefgh" -def exercise_logging(logger): +def exercise_logging(logger, message="C"): set_trace_ids() - logger.warning("C") + logger.warning(message) def get_metadata_string(log_message, is_txn): @@ -82,3 +82,14 @@ def test(): assert logger.caplog.records[0] == get_metadata_string("C", False) test() + + +@reset_core_stats_engine() +def test_local_log_decoration_dict_message(logger): + @validate_log_event_count(1) + @background_task() + def test(): + exercise_logging(logger, {"message": "dict_message"}) + assert logger.caplog.records[0] == get_metadata_string("{'message': 'dict_message'}", True) + + test() diff --git a/tests/logger_logging/test_log_forwarding.py b/tests/logger_logging/test_log_forwarding.py index c622fef00..6d5dbfc22 100644 --- a/tests/logger_logging/test_log_forwarding.py +++ b/tests/logger_logging/test_log_forwarding.py @@ -19,7 +19,9 @@ from newrelic.api.transaction import current_transaction 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_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 @@ -43,15 +45,20 @@ def exercise_logging(logger): logger.error({"message": "F", "attr": 1}) logger.warning({"attr": "G"}) - - assert len(logger.caplog.records) == 3 + + assert len(logger.caplog.records) == 5 def update_all(events, attrs): for event in events: event.update(attrs) -_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"} _common_attributes_trace_linking.update(_common_attributes_service_linking) @@ -65,14 +72,11 @@ def update_all(events, attrs): update_all(_test_logging_inside_transaction_events, _common_attributes_trace_linking) +@validate_log_events(_test_logging_inside_transaction_events) +@validate_log_event_count(5) +@background_task() def test_logging_inside_transaction(logger): - @validate_log_events(_test_logging_inside_transaction_events) - @validate_log_event_count(5) - @background_task() - def test(): - exercise_logging(logger) - - test() + exercise_logging(logger) _test_logging_outside_transaction_events = [ @@ -86,13 +90,52 @@ def test(): @reset_core_stats_engine() +@validate_log_events_outside_transaction(_test_logging_outside_transaction_events) +@validate_log_event_count_outside_transaction(5) def test_logging_outside_transaction(logger): - @validate_log_events_outside_transaction(_test_logging_outside_transaction_events) - @validate_log_event_count_outside_transaction(5) - def test(): - exercise_logging(logger) - - test() + exercise_logging(logger) + + +# Default context attrs +@validate_log_events( + [ + { # Fixed attributes + "message": "context_attrs: arg1", + "context.args": "('arg1',)", + "context.filename": "test_log_forwarding.py", + "context.funcName": "test_logging_context_attributes", + "context.levelname": "ERROR", + "context.levelno": 40, + "context.module": "test_log_forwarding", + "context.name": "my_app", + "context.pathname": str(__file__), + "context.processName": "MainProcess", + "context.threadName": "MainThread", + } + ], + required_attrs=[ # Variable attributes + "context.created", + "context.lineno", + "context.msecs", + "context.process", + "context.relativeCreated", + "context.thread", + ], + forgone_attrs=["context.exc_info"], +) +@validate_log_events([{"message": "extras", "context.extra_attr": 1}]) # Extras on logger calls +@validate_log_events([{"message": "stack_info"}], required_attrs=["context.stack_info"]) # Stack info generation +@validate_log_events([{"message": "exc_info"}], required_attrs=["context.exc_info"]) # Exception info generation +@validate_log_event_count(4) +@background_task() +def test_logging_context_attributes(logger): + logger.error("context_attrs: %s", "arg1") + logger.error("extras", extra={"extra_attr": 1}) + logger.error("stack_info", stack_info=True) + try: + raise RuntimeError("Oops") + except Exception: + logger.error("exc_info", exc_info=True) @reset_core_stats_engine() From 9409bed060ef79570fee28eedd4a26768ddfd978 Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Thu, 21 Dec 2023 17:30:53 -0800 Subject: [PATCH 08/19] Add logging context test for py2 --- tests/logger_logging/test_log_forwarding.py | 13 ++++++++++--- 1 file changed, 10 insertions(+), 3 deletions(-) diff --git a/tests/logger_logging/test_log_forwarding.py b/tests/logger_logging/test_log_forwarding.py index 6d5dbfc22..fe281288e 100644 --- a/tests/logger_logging/test_log_forwarding.py +++ b/tests/logger_logging/test_log_forwarding.py @@ -17,7 +17,11 @@ from newrelic.api.background_task import background_task from newrelic.api.time_trace import current_trace from newrelic.api.transaction import current_transaction + +from newrelic.packages import six + from testing_support.fixtures import reset_core_stats_engine +from testing_support.util import conditional_decorator 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, @@ -124,19 +128,22 @@ def test_logging_outside_transaction(logger): forgone_attrs=["context.exc_info"], ) @validate_log_events([{"message": "extras", "context.extra_attr": 1}]) # Extras on logger calls -@validate_log_events([{"message": "stack_info"}], required_attrs=["context.stack_info"]) # Stack info generation @validate_log_events([{"message": "exc_info"}], required_attrs=["context.exc_info"]) # Exception info generation -@validate_log_event_count(4) +# Stack info generation only on Py3 +@conditional_decorator(six.PY3, validate_log_events([{"message": "stack_info"}], required_attrs=["context.stack_info"])) +@validate_log_event_count(4 if six.PY3 else 3) @background_task() def test_logging_context_attributes(logger): logger.error("context_attrs: %s", "arg1") logger.error("extras", extra={"extra_attr": 1}) - logger.error("stack_info", stack_info=True) + try: raise RuntimeError("Oops") except Exception: logger.error("exc_info", exc_info=True) + if six.PY3: + logger.error("stack_info", stack_info=True) @reset_core_stats_engine() def test_logging_newrelic_logs_not_forwarded(logger): From 300641516b0d0601f875e29f9fa6d5621d22da5c Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Fri, 22 Dec 2023 13:36:52 -0800 Subject: [PATCH 09/19] Logically separate attribute tests --- .../test_attribute_forwarding.py | 65 ------------- tests/logger_logging/test_attributes.py | 93 +++++++++++++++++++ tests/logger_logging/test_log_forwarding.py | 60 +----------- 3 files changed, 97 insertions(+), 121 deletions(-) delete mode 100644 tests/logger_logging/test_attribute_forwarding.py create mode 100644 tests/logger_logging/test_attributes.py diff --git a/tests/logger_logging/test_attribute_forwarding.py b/tests/logger_logging/test_attribute_forwarding.py deleted file mode 100644 index eea549e70..000000000 --- a/tests/logger_logging/test_attribute_forwarding.py +++ /dev/null @@ -1,65 +0,0 @@ -# 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 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 newrelic.api.background_task import background_task - -_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_attributes.py b/tests/logger_logging/test_attributes.py new file mode 100644 index 000000000..4fd23fd65 --- /dev/null +++ b/tests/logger_logging/test_attributes.py @@ -0,0 +1,93 @@ +# 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. + +import pytest + +from newrelic.api.background_task import background_task + +from newrelic.packages import six + +from testing_support.validators.validate_log_event_count import validate_log_event_count +from testing_support.validators.validate_log_events import validate_log_events + + +@validate_log_events( + [ + { # Fixed attributes + "message": "context_attrs: arg1", + "context.args": "('arg1',)", + "context.filename": "test_attributes.py", + "context.funcName": "test_logging_default_context_attributes", + "context.levelname": "ERROR", + "context.levelno": 40, + "context.module": "test_attributes", + "context.name": "my_app", + "context.pathname": str(__file__), + "context.processName": "MainProcess", + "context.threadName": "MainThread", + } + ], + required_attrs=[ # Variable attributes + "context.created", + "context.lineno", + "context.msecs", + "context.process", + "context.relativeCreated", + "context.thread", + ], + forgone_attrs=["context.exc_info", "context.stack_info"], # Attributes not included by default +) +@validate_log_event_count(1) +@background_task() +def test_logging_default_context_attributes(logger): + logger.error("context_attrs: %s", "arg1") + + +@validate_log_events([{"message": "extras", "context.extra_attr": 1}]) +@validate_log_event_count(1) +@background_task() +def test_logging_extra_attributes(logger): + logger.error("extras", extra={"extra_attr": 1}) + + +@validate_log_events([{"message": "exc_info"}], required_attrs=["context.exc_info"]) +@validate_log_event_count(1) +@background_task() +def test_logging_exc_info_context_attributes(logger): + try: + raise RuntimeError("Oops") + except Exception: + logger.error("exc_info", exc_info=True) + + +@pytest.mark.skipif(six.PY2, reason="stack_info on log messages not available in Python 2.") +@validate_log_events([{"message": "stack_info"}], required_attrs=["context.stack_info"]) +@validate_log_event_count(1) +@background_task() +def test_logging_stack_info_context_attributes(logger): + logger.error("stack_info", stack_info=True) + + +@validate_log_events([{"message": "A", "message.attr": 1}]) +@validate_log_event_count(1) +@background_task() +def test_logging_message_attributes(logger): + logger.error({"message": "A", "attr": 1}) + + +@validate_log_events([{"message.attr": 1}]) +@validate_log_event_count(1) +@background_task() +def test_logging_attributes_only(logger): + logger.error({"attr": 1}) diff --git a/tests/logger_logging/test_log_forwarding.py b/tests/logger_logging/test_log_forwarding.py index fe281288e..7625cc597 100644 --- a/tests/logger_logging/test_log_forwarding.py +++ b/tests/logger_logging/test_log_forwarding.py @@ -45,12 +45,9 @@ def exercise_logging(logger): logger.info("B") logger.warning("C") logger.error("D") - logger.critical("E") + logger.critical({"message": "E"}) - logger.error({"message": "F", "attr": 1}) - logger.warning({"attr": "G"}) - - assert len(logger.caplog.records) == 5 + assert len(logger.caplog.records) == 3 def update_all(events, attrs): for event in events: @@ -70,14 +67,12 @@ def update_all(events, attrs): {"message": "C", "level": "WARNING"}, {"message": "D", "level": "ERROR"}, {"message": "E", "level": "CRITICAL"}, - {"message": "F", "level": "ERROR", "message.attr": 1}, - {"message.attr": "G", "level": "WARNING"}, ] update_all(_test_logging_inside_transaction_events, _common_attributes_trace_linking) @validate_log_events(_test_logging_inside_transaction_events) -@validate_log_event_count(5) +@validate_log_event_count(3) @background_task() def test_logging_inside_transaction(logger): exercise_logging(logger) @@ -87,64 +82,17 @@ def test_logging_inside_transaction(logger): {"message": "C", "level": "WARNING"}, {"message": "D", "level": "ERROR"}, {"message": "E", "level": "CRITICAL"}, - {"message": "F", "level": "ERROR", "message.attr": 1}, - {"message.attr": "G", "level": "WARNING"}, ] update_all(_test_logging_outside_transaction_events, _common_attributes_service_linking) @reset_core_stats_engine() @validate_log_events_outside_transaction(_test_logging_outside_transaction_events) -@validate_log_event_count_outside_transaction(5) +@validate_log_event_count_outside_transaction(3) def test_logging_outside_transaction(logger): exercise_logging(logger) -# Default context attrs -@validate_log_events( - [ - { # Fixed attributes - "message": "context_attrs: arg1", - "context.args": "('arg1',)", - "context.filename": "test_log_forwarding.py", - "context.funcName": "test_logging_context_attributes", - "context.levelname": "ERROR", - "context.levelno": 40, - "context.module": "test_log_forwarding", - "context.name": "my_app", - "context.pathname": str(__file__), - "context.processName": "MainProcess", - "context.threadName": "MainThread", - } - ], - required_attrs=[ # Variable attributes - "context.created", - "context.lineno", - "context.msecs", - "context.process", - "context.relativeCreated", - "context.thread", - ], - forgone_attrs=["context.exc_info"], -) -@validate_log_events([{"message": "extras", "context.extra_attr": 1}]) # Extras on logger calls -@validate_log_events([{"message": "exc_info"}], required_attrs=["context.exc_info"]) # Exception info generation -# Stack info generation only on Py3 -@conditional_decorator(six.PY3, validate_log_events([{"message": "stack_info"}], required_attrs=["context.stack_info"])) -@validate_log_event_count(4 if six.PY3 else 3) -@background_task() -def test_logging_context_attributes(logger): - logger.error("context_attrs: %s", "arg1") - logger.error("extras", extra={"extra_attr": 1}) - - try: - raise RuntimeError("Oops") - except Exception: - logger.error("exc_info", exc_info=True) - - if six.PY3: - logger.error("stack_info", stack_info=True) - @reset_core_stats_engine() def test_logging_newrelic_logs_not_forwarded(logger): @validate_log_event_count(0) From 0e920cfe17a8ff81680024a21502a9d1eb35ae75 Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Fri, 22 Dec 2023 13:37:53 -0800 Subject: [PATCH 10/19] Clean out imports --- tests/logger_logging/test_log_forwarding.py | 3 --- tests/logger_logging/test_logging_handler.py | 10 +--------- 2 files changed, 1 insertion(+), 12 deletions(-) diff --git a/tests/logger_logging/test_log_forwarding.py b/tests/logger_logging/test_log_forwarding.py index 7625cc597..67b540456 100644 --- a/tests/logger_logging/test_log_forwarding.py +++ b/tests/logger_logging/test_log_forwarding.py @@ -18,10 +18,7 @@ from newrelic.api.time_trace import current_trace from newrelic.api.transaction import current_transaction -from newrelic.packages import six - from testing_support.fixtures import reset_core_stats_engine -from testing_support.util import conditional_decorator 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, diff --git a/tests/logger_logging/test_logging_handler.py b/tests/logger_logging/test_logging_handler.py index dce99f9f8..a5dd878e7 100644 --- a/tests/logger_logging/test_logging_handler.py +++ b/tests/logger_logging/test_logging_handler.py @@ -15,7 +15,7 @@ import logging import pytest -from conftest import logger as conf_logger + from testing_support.fixtures import ( override_application_settings, reset_core_stats_engine, @@ -35,14 +35,6 @@ 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_trace_linking = {"span.id": "abcdefgh", "trace.id": "abcdefgh12345678"} - @pytest.fixture(scope="function") def uninstrument_logging(): From 3bd9ab820696b7f0237ea4210ca33f719955e067 Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Fri, 22 Dec 2023 14:12:25 -0800 Subject: [PATCH 11/19] Fix failing tests --- newrelic/hooks/logger_logging.py | 2 +- tests/logger_logging/test_attributes.py | 3 +-- tests/logger_logging/test_logging_handler.py | 2 ++ 3 files changed, 4 insertions(+), 3 deletions(-) diff --git a/newrelic/hooks/logger_logging.py b/newrelic/hooks/logger_logging.py index a745b238e..2d6ea2f4e 100644 --- a/newrelic/hooks/logger_logging.py +++ b/newrelic/hooks/logger_logging.py @@ -81,7 +81,7 @@ def wrap_callHandlers(wrapped, instance, args, kwargs): if settings.application_logging.forwarding and settings.application_logging.forwarding.enabled: try: message = record.msg - if isinstance(message, dict): + if not isinstance(message, dict): # Allow python to convert the message to a string and template it with args. message = record.getMessage() diff --git a/tests/logger_logging/test_attributes.py b/tests/logger_logging/test_attributes.py index 4fd23fd65..f125b8426 100644 --- a/tests/logger_logging/test_attributes.py +++ b/tests/logger_logging/test_attributes.py @@ -46,7 +46,6 @@ "context.relativeCreated", "context.thread", ], - forgone_attrs=["context.exc_info", "context.stack_info"], # Attributes not included by default ) @validate_log_event_count(1) @background_task() @@ -61,7 +60,7 @@ def test_logging_extra_attributes(logger): logger.error("extras", extra={"extra_attr": 1}) -@validate_log_events([{"message": "exc_info"}], required_attrs=["context.exc_info"]) +@validate_log_events([{"message": "exc_info"}], required_attrs=["context.exc_info", "context.exc_text"]) @validate_log_event_count(1) @background_task() def test_logging_exc_info_context_attributes(logger): diff --git a/tests/logger_logging/test_logging_handler.py b/tests/logger_logging/test_logging_handler.py index a5dd878e7..8a892624e 100644 --- a/tests/logger_logging/test_logging_handler.py +++ b/tests/logger_logging/test_logging_handler.py @@ -16,6 +16,8 @@ import pytest +from conftest import logger as conf_logger + from testing_support.fixtures import ( override_application_settings, reset_core_stats_engine, From 091c87424a7a84f5bdf0318cce0d616cf7c83794 Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Fri, 22 Dec 2023 14:18:36 -0800 Subject: [PATCH 12/19] Remove logging instrumentation changes for new PR --- newrelic/hooks/logger_logging.py | 24 ++--- tests/logger_logging/conftest.py | 1 - .../test_attribute_forwarding.py | 65 +++++++++++++ tests/logger_logging/test_attributes.py | 92 ------------------- tests/logger_logging/test_local_decorating.py | 15 +-- tests/logger_logging/test_log_forwarding.py | 36 ++++---- tests/logger_logging/test_logging_handler.py | 10 +- 7 files changed, 105 insertions(+), 138 deletions(-) create mode 100644 tests/logger_logging/test_attribute_forwarding.py delete mode 100644 tests/logger_logging/test_attributes.py diff --git a/newrelic/hooks/logger_logging.py b/newrelic/hooks/logger_logging.py index 2d6ea2f4e..80cf0fd24 100644 --- a/newrelic/hooks/logger_logging.py +++ b/newrelic/hooks/logger_logging.py @@ -27,7 +27,7 @@ from urllib.parse import quote -IGNORED_LOG_RECORD_KEYS = set(["message", "msg"]) +DEFAULT_LOG_RECORD_KEYS = frozenset(set(vars(LogRecord("", 0, "", 0, "", (), None))) | {"message"}) def add_nr_linking_metadata(message): @@ -52,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) @@ -80,17 +89,10 @@ def wrap_callHandlers(wrapped, instance, args, kwargs): if settings.application_logging.forwarding and settings.application_logging.forwarding.enabled: try: - message = record.msg - if not isinstance(message, dict): - # Allow python to convert the message to a string and template it with args. - message = record.getMessage() - - # Grab and filter context attributes from log record - record_attrs = vars(record) - context_attrs = {k: record_attrs[k] for k in vars(record) if k not in IGNORED_LOG_RECORD_KEYS} - + message = record.getMessage() + attrs = filter_record_attributes(record) record_log_event( - message=message, level=level_name, timestamp=int(record.created * 1000), attributes=context_attrs + message=message, level=level_name, timestamp=int(record.created * 1000), attributes=attrs ) except Exception: pass diff --git a/tests/logger_logging/conftest.py b/tests/logger_logging/conftest.py index b9ecf8526..46e8f4ec3 100644 --- a/tests/logger_logging/conftest.py +++ b/tests/logger_logging/conftest.py @@ -26,7 +26,6 @@ "debug.record_transaction_failure": True, "application_logging.enabled": True, "application_logging.forwarding.enabled": True, - "application_logging.forwarding.context_data.enabled": True, "application_logging.metrics.enabled": True, "application_logging.local_decorating.enabled": True, "event_harvest_config.harvest_limits.log_event_data": 100000, diff --git a/tests/logger_logging/test_attribute_forwarding.py b/tests/logger_logging/test_attribute_forwarding.py new file mode 100644 index 000000000..eea549e70 --- /dev/null +++ b/tests/logger_logging/test_attribute_forwarding.py @@ -0,0 +1,65 @@ +# 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 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 newrelic.api.background_task import background_task + +_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_attributes.py b/tests/logger_logging/test_attributes.py deleted file mode 100644 index f125b8426..000000000 --- a/tests/logger_logging/test_attributes.py +++ /dev/null @@ -1,92 +0,0 @@ -# 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. - -import pytest - -from newrelic.api.background_task import background_task - -from newrelic.packages import six - -from testing_support.validators.validate_log_event_count import validate_log_event_count -from testing_support.validators.validate_log_events import validate_log_events - - -@validate_log_events( - [ - { # Fixed attributes - "message": "context_attrs: arg1", - "context.args": "('arg1',)", - "context.filename": "test_attributes.py", - "context.funcName": "test_logging_default_context_attributes", - "context.levelname": "ERROR", - "context.levelno": 40, - "context.module": "test_attributes", - "context.name": "my_app", - "context.pathname": str(__file__), - "context.processName": "MainProcess", - "context.threadName": "MainThread", - } - ], - required_attrs=[ # Variable attributes - "context.created", - "context.lineno", - "context.msecs", - "context.process", - "context.relativeCreated", - "context.thread", - ], -) -@validate_log_event_count(1) -@background_task() -def test_logging_default_context_attributes(logger): - logger.error("context_attrs: %s", "arg1") - - -@validate_log_events([{"message": "extras", "context.extra_attr": 1}]) -@validate_log_event_count(1) -@background_task() -def test_logging_extra_attributes(logger): - logger.error("extras", extra={"extra_attr": 1}) - - -@validate_log_events([{"message": "exc_info"}], required_attrs=["context.exc_info", "context.exc_text"]) -@validate_log_event_count(1) -@background_task() -def test_logging_exc_info_context_attributes(logger): - try: - raise RuntimeError("Oops") - except Exception: - logger.error("exc_info", exc_info=True) - - -@pytest.mark.skipif(six.PY2, reason="stack_info on log messages not available in Python 2.") -@validate_log_events([{"message": "stack_info"}], required_attrs=["context.stack_info"]) -@validate_log_event_count(1) -@background_task() -def test_logging_stack_info_context_attributes(logger): - logger.error("stack_info", stack_info=True) - - -@validate_log_events([{"message": "A", "message.attr": 1}]) -@validate_log_event_count(1) -@background_task() -def test_logging_message_attributes(logger): - logger.error({"message": "A", "attr": 1}) - - -@validate_log_events([{"message.attr": 1}]) -@validate_log_event_count(1) -@background_task() -def test_logging_attributes_only(logger): - logger.error({"attr": 1}) diff --git a/tests/logger_logging/test_local_decorating.py b/tests/logger_logging/test_local_decorating.py index 7b420375c..d4917eff5 100644 --- a/tests/logger_logging/test_local_decorating.py +++ b/tests/logger_logging/test_local_decorating.py @@ -35,10 +35,10 @@ def set_trace_ids(): trace.guid = "abcdefgh" -def exercise_logging(logger, message="C"): +def exercise_logging(logger): set_trace_ids() - logger.warning(message) + logger.warning("C") def get_metadata_string(log_message, is_txn): @@ -82,14 +82,3 @@ def test(): assert logger.caplog.records[0] == get_metadata_string("C", False) test() - - -@reset_core_stats_engine() -def test_local_log_decoration_dict_message(logger): - @validate_log_event_count(1) - @background_task() - def test(): - exercise_logging(logger, {"message": "dict_message"}) - assert logger.caplog.records[0] == get_metadata_string("{'message': 'dict_message'}", True) - - test() diff --git a/tests/logger_logging/test_log_forwarding.py b/tests/logger_logging/test_log_forwarding.py index 67b540456..ee6c689b7 100644 --- a/tests/logger_logging/test_log_forwarding.py +++ b/tests/logger_logging/test_log_forwarding.py @@ -17,12 +17,9 @@ from newrelic.api.background_task import background_task from newrelic.api.time_trace import current_trace from newrelic.api.transaction import current_transaction - 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_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 @@ -42,8 +39,8 @@ def exercise_logging(logger): logger.info("B") logger.warning("C") logger.error("D") - logger.critical({"message": "E"}) - + logger.critical("E") + assert len(logger.caplog.records) == 3 def update_all(events, attrs): @@ -51,12 +48,7 @@ def update_all(events, attrs): event.update(attrs) -_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"} _common_attributes_trace_linking.update(_common_attributes_service_linking) @@ -68,11 +60,14 @@ def update_all(events, attrs): update_all(_test_logging_inside_transaction_events, _common_attributes_trace_linking) -@validate_log_events(_test_logging_inside_transaction_events) -@validate_log_event_count(3) -@background_task() def test_logging_inside_transaction(logger): - exercise_logging(logger) + @validate_log_events(_test_logging_inside_transaction_events) + @validate_log_event_count(3) + @background_task() + def test(): + exercise_logging(logger) + + test() _test_logging_outside_transaction_events = [ @@ -84,10 +79,13 @@ def test_logging_inside_transaction(logger): @reset_core_stats_engine() -@validate_log_events_outside_transaction(_test_logging_outside_transaction_events) -@validate_log_event_count_outside_transaction(3) def test_logging_outside_transaction(logger): - exercise_logging(logger) + @validate_log_events_outside_transaction(_test_logging_outside_transaction_events) + @validate_log_event_count_outside_transaction(3) + def test(): + exercise_logging(logger) + + test() @reset_core_stats_engine() diff --git a/tests/logger_logging/test_logging_handler.py b/tests/logger_logging/test_logging_handler.py index 8a892624e..dce99f9f8 100644 --- a/tests/logger_logging/test_logging_handler.py +++ b/tests/logger_logging/test_logging_handler.py @@ -15,9 +15,7 @@ import logging import pytest - from conftest import logger as conf_logger - from testing_support.fixtures import ( override_application_settings, reset_core_stats_engine, @@ -37,6 +35,14 @@ 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_trace_linking = {"span.id": "abcdefgh", "trace.id": "abcdefgh12345678"} + @pytest.fixture(scope="function") def uninstrument_logging(): From 6b396d228ca3669ffe8f0331693336b83ab4b5ac Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Thu, 4 Jan 2024 12:10:46 -0800 Subject: [PATCH 13/19] Add test for record log event edge cases --- tests/agent_features/test_log_events.py | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/tests/agent_features/test_log_events.py b/tests/agent_features/test_log_events.py index 42be365c1..d358b6d2f 100644 --- a/tests/agent_features/test_log_events.py +++ b/tests/agent_features/test_log_events.py @@ -75,11 +75,14 @@ def exercise_record_log_event(): record_log_event(None, attributes={"attributes_only": "value"}) record_log_event({"attributes_only": "value"}) record_log_event({"message": "dict_message"}) + record_log_event({"message": 123}) # Unsent due to message content missing record_log_event("") record_log_event(" ") + record_log_event(NonPrintableObject()) record_log_event({"message": ""}) + record_log_event({"message": NonPrintableObject()}) record_log_event({"filtered_attribute": "should_be_removed"}) record_log_event(None) @@ -130,6 +133,7 @@ def exercise_record_log_event(): {"context.attributes_only": "value"}, {"message.attributes_only": "value"}, {"message": "dict_message"}, + {"message": "123"}, ] _exercise_record_log_event_inside_transaction_events = [ combine_dicts(_common_attributes_trace_linking, log) for log in _exercise_record_log_event_events From d889358647b4e1ac5c10153678ce88d493726c6d Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Thu, 4 Jan 2024 12:11:02 -0800 Subject: [PATCH 14/19] Update record_log_event for code review --- newrelic/api/transaction.py | 35 ++++++++++++++++------------------- newrelic/core/stats_engine.py | 35 ++++++++++++++++------------------- 2 files changed, 32 insertions(+), 38 deletions(-) diff --git a/newrelic/api/transaction.py b/newrelic/api/transaction.py index fa6794cc2..99360d744 100644 --- a/newrelic/api/transaction.py +++ b/newrelic/api/transaction.py @@ -1539,35 +1539,32 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=None, timestamp = timestamp if timestamp is not None else time.time() level = str(level) if level is not None else "UNKNOWN" + context_attributes = attributes # Name reassigned for clarity # Unpack message and attributes from dict inputs if isinstance(message, dict): message_attributes = {k: v for k, v in message.items() if k != "message"} - message = str(message.get("message", "")) + message = message.get("message", "") else: message_attributes = None - # Exit early for invalid message type after unpacking - is_string = isinstance(message, six.string_types) - if message is not None and not is_string: - _logger.debug("record_log_event called where message was not found. No log event will be sent.") - return - - # Exit early if no message or attributes found - no_message = not message or message.isspace() - if not attributes and not message_attributes and no_message: - _logger.debug("record_log_event called where message was missing, and no attributes found. No log event will be sent.") - return - - # Truncate the now unpacked and string converted message - if is_string: + # Coerce message into a string type + if message is not None and not isinstance(message, six.string_types): + try: + message = str(message) + except Exception: + # Exit early for invalid message type after unpacking + _logger.debug("record_log_event called where message could not be converted to a string type. No log event will be sent.") + return + + # Truncate the now unpacked and string converted message message = truncate(message, MAX_LOG_MESSAGE_LENGTH) # Collect attributes from linking metadata, context data, and message attributes collected_attributes = {} if settings and settings.application_logging.forwarding.context_data.enabled: - if attributes: - context_attributes = resolve_logging_context_attributes(attributes, settings.attribute_filter, "context.") + if context_attributes: + context_attributes = resolve_logging_context_attributes(context_attributes, settings.attribute_filter, "context.") if context_attributes: collected_attributes.update(context_attributes) @@ -1577,8 +1574,8 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=None, collected_attributes.update(message_attributes) # Exit early if no message or attributes found after filtering - if not collected_attributes and no_message: - _logger.debug("record_log_event called where message was missing, and no attributes found. No log event will be sent.") + if (not message or message.isspace()) and not context_attributes and not message_attributes: + _logger.debug("record_log_event called where message was not found, and no attributes were found. No log event will be sent.") return # Finally, add in linking attributes after checking that there is a valid message or at least 1 attribute diff --git a/newrelic/core/stats_engine.py b/newrelic/core/stats_engine.py index 3dc682731..c913cbe81 100644 --- a/newrelic/core/stats_engine.py +++ b/newrelic/core/stats_engine.py @@ -1232,35 +1232,32 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=None, timestamp = timestamp if timestamp is not None else time.time() level = str(level) if level is not None else "UNKNOWN" + context_attributes = attributes # Name reassigned for clarity # Unpack message and attributes from dict inputs if isinstance(message, dict): message_attributes = {k: v for k, v in message.items() if k != "message"} - message = str(message.get("message", "")) + message = message.get("message", "") else: message_attributes = None - # Exit early for invalid message type after unpacking - is_string = isinstance(message, six.string_types) - if message is not None and not is_string: - _logger.debug("record_log_event called where message was not found. No log event will be sent.") - return - - # Exit early if no message or attributes found - no_message = not message or message.isspace() - if not attributes and not message_attributes and no_message: - _logger.debug("record_log_event called where message was missing, and no attributes found. No log event will be sent.") - return - - # Truncate the now unpacked and string converted message - if is_string: + # Coerce message into a string type + if message is not None and not isinstance(message, six.string_types): + try: + message = str(message) + except Exception: + # Exit early for invalid message type after unpacking + _logger.debug("record_log_event called where message could not be converted to a string type. No log event will be sent.") + return + + # Truncate the now unpacked and string converted message message = truncate(message, MAX_LOG_MESSAGE_LENGTH) # Collect attributes from linking metadata, context data, and message attributes collected_attributes = {} if settings and settings.application_logging.forwarding.context_data.enabled: - if attributes: - context_attributes = resolve_logging_context_attributes(attributes, settings.attribute_filter, "context.") + if context_attributes: + context_attributes = resolve_logging_context_attributes(context_attributes, settings.attribute_filter, "context.") if context_attributes: collected_attributes.update(context_attributes) @@ -1270,8 +1267,8 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=None, collected_attributes.update(message_attributes) # Exit early if no message or attributes found after filtering - if not collected_attributes and no_message: - _logger.debug("record_log_event called where message was missing, and no attributes found. No log event will be sent.") + if (not message or message.isspace()) and not context_attributes and not message_attributes: + _logger.debug("record_log_event called where message was not found, and no attributes were found. No log event will be sent.") return # Finally, add in linking attributes after checking that there is a valid message or at least 1 attribute From 10da9642718f99cdc99a027b051fa843a27a78f8 Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Thu, 4 Jan 2024 12:14:04 -0800 Subject: [PATCH 15/19] Fix truncation --- newrelic/api/transaction.py | 17 +++++++++-------- newrelic/core/stats_engine.py | 17 +++++++++-------- 2 files changed, 18 insertions(+), 16 deletions(-) diff --git a/newrelic/api/transaction.py b/newrelic/api/transaction.py index 99360d744..44a7963ec 100644 --- a/newrelic/api/transaction.py +++ b/newrelic/api/transaction.py @@ -1548,14 +1548,15 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=None, else: message_attributes = None - # Coerce message into a string type - if message is not None and not isinstance(message, six.string_types): - try: - message = str(message) - except Exception: - # Exit early for invalid message type after unpacking - _logger.debug("record_log_event called where message could not be converted to a string type. No log event will be sent.") - return + if message is not None: + # Coerce message into a string type + if not isinstance(message, six.string_types): + try: + message = str(message) + except Exception: + # Exit early for invalid message type after unpacking + _logger.debug("record_log_event called where message could not be converted to a string type. No log event will be sent.") + return # Truncate the now unpacked and string converted message message = truncate(message, MAX_LOG_MESSAGE_LENGTH) diff --git a/newrelic/core/stats_engine.py b/newrelic/core/stats_engine.py index c913cbe81..b66cc94b0 100644 --- a/newrelic/core/stats_engine.py +++ b/newrelic/core/stats_engine.py @@ -1241,14 +1241,15 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=None, else: message_attributes = None - # Coerce message into a string type - if message is not None and not isinstance(message, six.string_types): - try: - message = str(message) - except Exception: - # Exit early for invalid message type after unpacking - _logger.debug("record_log_event called where message could not be converted to a string type. No log event will be sent.") - return + if message is not None: + # Coerce message into a string type + if not isinstance(message, six.string_types): + try: + message = str(message) + except Exception: + # Exit early for invalid message type after unpacking + _logger.debug("record_log_event called where message could not be converted to a string type. No log event will be sent.") + return # Truncate the now unpacked and string converted message message = truncate(message, MAX_LOG_MESSAGE_LENGTH) From a6a6be3ec261e476ccdd2f24a0229263de62b661 Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Fri, 5 Jan 2024 15:17:03 -0800 Subject: [PATCH 16/19] Move safe_json_encode back to api.log as it's unused elsewhere --- newrelic/api/log.py | 23 ++++++++++++++++++++++- newrelic/api/transaction.py | 1 - newrelic/common/encoding_utils.py | 22 ---------------------- newrelic/core/stats_engine.py | 2 +- 4 files changed, 23 insertions(+), 25 deletions(-) diff --git a/newrelic/api/log.py b/newrelic/api/log.py index cdd6737e3..d178eafba 100644 --- a/newrelic/api/log.py +++ b/newrelic/api/log.py @@ -21,7 +21,6 @@ from newrelic.api.time_trace import get_linking_metadata from newrelic.api.transaction import current_transaction, record_log_event from newrelic.common import agent_http -from newrelic.common.encoding_utils import safe_json_encode from newrelic.common.object_names import parse_exc_info from newrelic.core.attribute import truncate from newrelic.core.config import global_settings, is_expected_error @@ -44,6 +43,28 @@ def format_exc_info(exc_info): return formatted +def safe_json_encode(obj, ignore_string_types=False, **kwargs): + # Performs the same operation as json_encode but replaces unserializable objects with a string containing their class name. + # If ignore_string_types is True, do not encode string types further. + # Currently used for safely encoding logging attributes. + + if ignore_string_types and isinstance(obj, (six.string_types, six.binary_type)): + return obj + + # Attempt to run through JSON serialization + try: + return json_encode(obj, **kwargs) + except Exception: + pass + + # If JSON serialization fails then return a repr + try: + return repr(obj) + except Exception: + # If repr fails then default to an unprinatable object name + return "" % type(obj).__name__ + + class NewRelicContextFormatter(Formatter): DEFAULT_LOG_RECORD_KEYS = frozenset(set(vars(LogRecord("", 0, "", 0, "", (), None))) | {"message"}) diff --git a/newrelic/api/transaction.py b/newrelic/api/transaction.py index 03b9ea01f..393f2c994 100644 --- a/newrelic/api/transaction.py +++ b/newrelic/api/transaction.py @@ -44,7 +44,6 @@ json_decode, json_encode, obfuscate, - safe_json_encode, snake_case, ) from newrelic.core.attribute import ( diff --git a/newrelic/common/encoding_utils.py b/newrelic/common/encoding_utils.py index f075d42d3..ed7dc3a15 100644 --- a/newrelic/common/encoding_utils.py +++ b/newrelic/common/encoding_utils.py @@ -113,28 +113,6 @@ def json_decode(s, **kwargs): return json.loads(s, **kwargs) -def safe_json_encode(obj, ignore_string_types=False, **kwargs): - # Performs the same operation as json_encode but replaces unserializable objects with a string containing their class name. - # If ignore_string_types is True, do not encode string types further. - # Currently used for safely encoding logging attributes. - - if ignore_string_types and isinstance(obj, (six.string_types, six.binary_type)): - return obj - - # Attempt to run through JSON serialization - try: - return json_encode(obj, **kwargs) - except Exception: - pass - - # If JSON serialization fails then return a repr - try: - return repr(obj) - except Exception: - # If repr fails then default to an unprinatable object name - return "" % type(obj).__name__ - - # Functions for obfuscating/deobfuscating text string based on an XOR # cipher. diff --git a/newrelic/core/stats_engine.py b/newrelic/core/stats_engine.py index b66cc94b0..4821a6d6e 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, safe_json_encode +from newrelic.common.encoding_utils import json_encode from newrelic.common.metric_utils import create_metric_identity from newrelic.common.object_names import parse_exc_info from newrelic.common.streaming_utils import StreamBuffer From dea5dcd9a86c92c0b19d253dcbf9a123ece6e2c2 Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Fri, 5 Jan 2024 15:17:28 -0800 Subject: [PATCH 17/19] Black formatting --- newrelic/api/transaction.py | 18 +++++++++++++----- newrelic/core/stats_engine.py | 18 +++++++++++++----- tests/agent_features/test_log_events.py | 12 +++++++++--- 3 files changed, 35 insertions(+), 13 deletions(-) diff --git a/newrelic/api/transaction.py b/newrelic/api/transaction.py index 393f2c994..4e6dea552 100644 --- a/newrelic/api/transaction.py +++ b/newrelic/api/transaction.py @@ -1554,9 +1554,11 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=None, message = str(message) except Exception: # Exit early for invalid message type after unpacking - _logger.debug("record_log_event called where message could not be converted to a string type. No log event will be sent.") + _logger.debug( + "record_log_event called where message could not be converted to a string type. No log event will be sent." + ) return - + # Truncate the now unpacked and string converted message message = truncate(message, MAX_LOG_MESSAGE_LENGTH) @@ -1564,18 +1566,24 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=None, collected_attributes = {} if settings and settings.application_logging.forwarding.context_data.enabled: if context_attributes: - context_attributes = resolve_logging_context_attributes(context_attributes, settings.attribute_filter, "context.") + context_attributes = resolve_logging_context_attributes( + context_attributes, settings.attribute_filter, "context." + ) if context_attributes: collected_attributes.update(context_attributes) if message_attributes: - message_attributes = resolve_logging_context_attributes(message_attributes, settings.attribute_filter, "message.") + message_attributes = resolve_logging_context_attributes( + message_attributes, settings.attribute_filter, "message." + ) if message_attributes: collected_attributes.update(message_attributes) # Exit early if no message or attributes found after filtering if (not message or message.isspace()) and not context_attributes and not message_attributes: - _logger.debug("record_log_event called where message was not found, and no attributes were found. No log event will be sent.") + _logger.debug( + "record_log_event called where message was not found, and no attributes were found. No log event will be sent." + ) return # Finally, add in linking attributes after checking that there is a valid message or at least 1 attribute diff --git a/newrelic/core/stats_engine.py b/newrelic/core/stats_engine.py index 4821a6d6e..ae700bf4e 100644 --- a/newrelic/core/stats_engine.py +++ b/newrelic/core/stats_engine.py @@ -1248,9 +1248,11 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=None, message = str(message) except Exception: # Exit early for invalid message type after unpacking - _logger.debug("record_log_event called where message could not be converted to a string type. No log event will be sent.") + _logger.debug( + "record_log_event called where message could not be converted to a string type. No log event will be sent." + ) return - + # Truncate the now unpacked and string converted message message = truncate(message, MAX_LOG_MESSAGE_LENGTH) @@ -1258,18 +1260,24 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=None, collected_attributes = {} if settings and settings.application_logging.forwarding.context_data.enabled: if context_attributes: - context_attributes = resolve_logging_context_attributes(context_attributes, settings.attribute_filter, "context.") + context_attributes = resolve_logging_context_attributes( + context_attributes, settings.attribute_filter, "context." + ) if context_attributes: collected_attributes.update(context_attributes) if message_attributes: - message_attributes = resolve_logging_context_attributes(message_attributes, settings.attribute_filter, "message.") + message_attributes = resolve_logging_context_attributes( + message_attributes, settings.attribute_filter, "message." + ) if message_attributes: collected_attributes.update(message_attributes) # Exit early if no message or attributes found after filtering if (not message or message.isspace()) and not context_attributes and not message_attributes: - _logger.debug("record_log_event called where message was not found, and no attributes were found. No log event will be sent.") + _logger.debug( + "record_log_event called where message was not found, and no attributes were found. No log event will be sent." + ) return # Finally, add in linking attributes after checking that there is a valid message or at least 1 attribute diff --git a/tests/agent_features/test_log_events.py b/tests/agent_features/test_log_events.py index d358b6d2f..fb9991a82 100644 --- a/tests/agent_features/test_log_events.py +++ b/tests/agent_features/test_log_events.py @@ -88,7 +88,11 @@ def exercise_record_log_event(): enable_log_forwarding = override_application_settings( - {"application_logging.forwarding.enabled": True, "application_logging.forwarding.context_data.enabled": True, "application_logging.forwarding.context_data.exclude": ["filtered_attribute"]} + { + "application_logging.forwarding.enabled": True, + "application_logging.forwarding.context_data.enabled": True, + "application_logging.forwarding.context_data.exclude": ["filtered_attribute"], + } ) disable_log_forwarding = override_application_settings({"application_logging.forwarding.enabled": False}) @@ -287,6 +291,7 @@ def test(): ("A*", "AB*", "ABC", False), ] + @pytest.mark.parametrize("prefix", ("context", "message")) @pytest.mark.parametrize("include,exclude,attr,expected", _test_record_log_event_context_attribute_filtering_params) def test_record_log_event_context_attribute_filtering_inside_transaction(include, exclude, attr, expected, prefix): @@ -349,10 +354,11 @@ def test(): ("", "*"), ] + @pytest.mark.parametrize("include,exclude", _test_record_log_event_linking_attribute_no_filtering_params) def test_record_log_event_linking_attribute_no_filtering_inside_transaction(include, exclude): attr = "entity.name" - + @override_application_settings( { "application_logging.forwarding.enabled": True, @@ -374,7 +380,7 @@ def test(): @reset_core_stats_engine() def test_record_log_event_linking_attribute_filtering_outside_transaction(include, exclude): attr = "entity.name" - + @override_application_settings( { "application_logging.forwarding.enabled": True, From 7ee6625f71bc0452f35d4d42fd52391cc69000e8 Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Fri, 5 Jan 2024 15:37:28 -0800 Subject: [PATCH 18/19] Add missing import --- newrelic/api/log.py | 1 + 1 file changed, 1 insertion(+) diff --git a/newrelic/api/log.py b/newrelic/api/log.py index d178eafba..f74339f46 100644 --- a/newrelic/api/log.py +++ b/newrelic/api/log.py @@ -21,6 +21,7 @@ from newrelic.api.time_trace import get_linking_metadata from newrelic.api.transaction import current_transaction, record_log_event from newrelic.common import agent_http +from newrelic.common.encoding_utils import 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 b9fa64a0520c5e99c3a39123d9877502a36c1a43 Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Mon, 8 Jan 2024 09:56:04 -0800 Subject: [PATCH 19/19] Fixup warning message --- newrelic/api/transaction.py | 2 +- newrelic/core/stats_engine.py | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/newrelic/api/transaction.py b/newrelic/api/transaction.py index 4e6dea552..b003312ab 100644 --- a/newrelic/api/transaction.py +++ b/newrelic/api/transaction.py @@ -1582,7 +1582,7 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=None, # Exit early if no message or attributes found after filtering if (not message or message.isspace()) and not context_attributes and not message_attributes: _logger.debug( - "record_log_event called where message was not found, and no attributes were found. No log event will be sent." + "record_log_event called where no message and no attributes were found. No log event will be sent." ) return diff --git a/newrelic/core/stats_engine.py b/newrelic/core/stats_engine.py index ae700bf4e..a13450585 100644 --- a/newrelic/core/stats_engine.py +++ b/newrelic/core/stats_engine.py @@ -1276,7 +1276,7 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=None, # Exit early if no message or attributes found after filtering if (not message or message.isspace()) and not context_attributes and not message_attributes: _logger.debug( - "record_log_event called where message was not found, and no attributes were found. No log event will be sent." + "record_log_event called where no message and no attributes were found. No log event will be sent." ) return