From 4d9c35770bdf2082cafb76b4a243c42bba9ab078 Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Thu, 7 Dec 2023 14:21:49 -0800 Subject: [PATCH 01/22] 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 0000000000..d7e29282c4 --- /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/22] 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 26b6bfa4ad..7a9c2b7d1f 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 e09637ee92..71e1845879 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/22] 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 80cf0fd248..7de67a3c85 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 d7e29282c4..65c78b26c3 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/22] 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 7a9c2b7d1f..38258b9da3 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 71e1845879..633b11854d 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/22] 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 38258b9da3..dec9ca887e 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 b7f6fb27db..42cff443ed 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 633b11854d..afd27c13d2 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 7de67a3c85..8f1ebcaccf 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 91585d2ff9..8a89b6e404 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 ee6c689b76..c622fef000 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/22] 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 dec9ca887e..fa6794cc26 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 afd27c13d2..3dc682731a 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 8a89b6e404..42be365c14 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/22] 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 8f1ebcaccf..a745b238e5 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 46e8f4ec3a..b9ecf85265 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 65c78b26c3..0000000000 --- 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 d4917eff59..7b420375cb 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 c622fef000..6d5dbfc229 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/22] 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 6d5dbfc229..fe281288e0 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/22] 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 eea549e709..0000000000 --- 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 0000000000..4fd23fd654 --- /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 fe281288e0..7625cc597d 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/22] 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 7625cc597d..67b5404562 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 dce99f9f8e..a5dd878e77 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/22] 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 a745b238e5..2d6ea2f4ed 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 4fd23fd654..f125b84268 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 a5dd878e77..8a892624e8 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 a4905f3dee7359269fc271312f9bfbcb24eae974 Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Thu, 28 Dec 2023 12:43:36 -0800 Subject: [PATCH 12/22] Structlog cleanup --- newrelic/hooks/logger_structlog.py | 11 +++++++---- 1 file changed, 7 insertions(+), 4 deletions(-) diff --git a/newrelic/hooks/logger_structlog.py b/newrelic/hooks/logger_structlog.py index 06d13aa4aa..30c4b137f1 100644 --- a/newrelic/hooks/logger_structlog.py +++ b/newrelic/hooks/logger_structlog.py @@ -12,14 +12,17 @@ # See the License for the specific language governing permissions and # limitations under the License. -from newrelic.common.object_wrapper import wrap_function_wrapper +import functools + +from newrelic.api.application import application_instance from newrelic.api.transaction import current_transaction, record_log_event +from newrelic.common.object_wrapper import wrap_function_wrapper, function_wrapper, ObjectProxy +from newrelic.common.signature import bind_args from newrelic.core.config import global_settings -from newrelic.api.application import application_instance from newrelic.hooks.logger_logging import add_nr_linking_metadata -from newrelic.common.signature import bind_args +@functools.cache def normalize_level_name(method_name): # Look up level number for method name, using result to look up level name for that level number. # Convert result to upper case, and default to UNKNOWN in case of errors or missing values. @@ -56,7 +59,7 @@ def wrap__process_event(wrapped, instance, args, kwargs): # Send log to processors for filtering, allowing any DropEvent exceptions that occur to prevent instrumentation from recording the log event. result = wrapped(method_name, event, event_kw) - + level_name = normalize_level_name(method_name) if settings.application_logging.metrics and settings.application_logging.metrics.enabled: From c20caa3de3bb58950d2abec2cbeacfbc8d30d6bb Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Thu, 28 Dec 2023 12:43:59 -0800 Subject: [PATCH 13/22] Attempting list instrumentation --- newrelic/hooks/logger_structlog.py | 19 +++++++++++++++++++ 1 file changed, 19 insertions(+) diff --git a/newrelic/hooks/logger_structlog.py b/newrelic/hooks/logger_structlog.py index 30c4b137f1..b82665b38f 100644 --- a/newrelic/hooks/logger_structlog.py +++ b/newrelic/hooks/logger_structlog.py @@ -37,6 +37,21 @@ def bind_process_event(method_name, event, event_kw): return method_name, event, event_kw +# class ProcessorsListWrapper(ObjectProxy): +# def __iter__(self): +# for processor in self.__wrapped__: +# yield wrap_processor(processor, self) + + +# def wrap_processor(processor, processors_proxy): +# @function_wrapper +# def _wrap_processor(wrapped, instance, args, kwargs): +# result = wrapped(*args, **kwargs) +# if isinstance(result, dict): +# processors_proxy._nr_event_dict = result +# return result + +# return _wrap_processor(processor) def wrap__process_event(wrapped, instance, args, kwargs): try: method_name, event, event_kw = bind_process_event(*args, **kwargs) @@ -57,6 +72,10 @@ def wrap__process_event(wrapped, instance, args, kwargs): if settings.application_logging.local_decorating and settings.application_logging.local_decorating.enabled: event = add_nr_linking_metadata(event) + # # Set up processor instrumentation on the logger if not configured + # if instance._processors and not hasattr(instance._processors, "_nr_instance"): + # instance._processors = ProcessorsListWrapper(instance._processors) + # Send log to processors for filtering, allowing any DropEvent exceptions that occur to prevent instrumentation from recording the log event. result = wrapped(method_name, event, event_kw) From 98376348f1d68be4ba957a02e84f3a4fd8dfcdd8 Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Thu, 28 Dec 2023 16:55:01 -0800 Subject: [PATCH 14/22] Structlog attributes support Co-authored-by: Lalleh Rafeei Co-authored-by: Uma Annamalai --- newrelic/hooks/logger_structlog.py | 83 ++++++++-------- tests/logger_structlog/conftest.py | 2 +- .../test_attribute_forwarding.py | 49 ---------- tests/logger_structlog/test_attributes.py | 98 +++++++++++++++++++ 4 files changed, 143 insertions(+), 89 deletions(-) delete mode 100644 tests/logger_structlog/test_attribute_forwarding.py create mode 100644 tests/logger_structlog/test_attributes.py diff --git a/newrelic/hooks/logger_structlog.py b/newrelic/hooks/logger_structlog.py index b82665b38f..1d6cf40af4 100644 --- a/newrelic/hooks/logger_structlog.py +++ b/newrelic/hooks/logger_structlog.py @@ -16,7 +16,7 @@ from newrelic.api.application import application_instance from newrelic.api.transaction import current_transaction, record_log_event -from newrelic.common.object_wrapper import wrap_function_wrapper, function_wrapper, ObjectProxy +from newrelic.common.object_wrapper import wrap_function_wrapper from newrelic.common.signature import bind_args from newrelic.core.config import global_settings from newrelic.hooks.logger_logging import add_nr_linking_metadata @@ -37,29 +37,7 @@ def bind_process_event(method_name, event, event_kw): return method_name, event, event_kw -# class ProcessorsListWrapper(ObjectProxy): -# def __iter__(self): -# for processor in self.__wrapped__: -# yield wrap_processor(processor, self) - - -# def wrap_processor(processor, processors_proxy): -# @function_wrapper -# def _wrap_processor(wrapped, instance, args, kwargs): -# result = wrapped(*args, **kwargs) -# if isinstance(result, dict): -# processors_proxy._nr_event_dict = result -# return result - -# return _wrap_processor(processor) -def wrap__process_event(wrapped, instance, args, kwargs): - try: - method_name, event, event_kw = bind_process_event(*args, **kwargs) - except TypeError: - return wrapped(*args, **kwargs) - - original_message = event # Save original undecorated message - +def new_relic_event_consumer(logger, level, event): transaction = current_transaction() if transaction: @@ -68,20 +46,28 @@ def wrap__process_event(wrapped, instance, args, kwargs): settings = global_settings() # Return early if application logging not enabled - if settings and settings.application_logging and settings.application_logging.enabled: - if settings.application_logging.local_decorating and settings.application_logging.local_decorating.enabled: - event = add_nr_linking_metadata(event) - - # # Set up processor instrumentation on the logger if not configured - # if instance._processors and not hasattr(instance._processors, "_nr_instance"): - # instance._processors = ProcessorsListWrapper(instance._processors) + if settings and settings.application_logging.enabled: + if isinstance(event, (str, bytes, bytearray)): + message = original_message = event + event_attrs = {} + elif isinstance(event, dict): + message = original_message = event.get("event", "") + event_attrs = {k: v for k, v in event.items() if k != "event"} + else: + # Unclear how to proceed, ignore log. Avoid logging an error message or we may incur an infinite loop. + return event - # Send log to processors for filtering, allowing any DropEvent exceptions that occur to prevent instrumentation from recording the log event. - result = wrapped(method_name, event, event_kw) + if settings.application_logging.local_decorating.enabled: + message = add_nr_linking_metadata(message) + if isinstance(event, (str, bytes, bytearray)): + event = message + elif isinstance(event, dict) and "event" in event: + # TODO CHECK ON THIS + event["event"] = message - level_name = normalize_level_name(method_name) + level_name = normalize_level_name(level) - if settings.application_logging.metrics and settings.application_logging.metrics.enabled: + if settings.application_logging.metrics.enabled: if transaction: transaction.record_custom_metric("Logging/lines", {"count": 1}) transaction.record_custom_metric("Logging/lines/%s" % level_name, {"count": 1}) @@ -91,15 +77,34 @@ def wrap__process_event(wrapped, instance, args, kwargs): application.record_custom_metric("Logging/lines", {"count": 1}) application.record_custom_metric("Logging/lines/%s" % level_name, {"count": 1}) - if settings.application_logging.forwarding and settings.application_logging.forwarding.enabled: + if settings.application_logging.forwarding.enabled: try: - record_log_event(original_message, level_name) + record_log_event(original_message, level_name, attributes=event_attrs) except Exception: pass - # Return the result from wrapped after we've recorded the resulting log event. - return result + return event + + +def wrap__process_event(wrapped, instance, args, kwargs): + transaction = current_transaction() + + if transaction: + settings = transaction.settings + else: + settings = global_settings() + + # Return early if application logging not enabled + if settings and settings.application_logging and settings.application_logging.enabled: + processors = instance._processors + if not processors: + instance._processors = [new_relic_event_consumer] + elif processors[-1] != new_relic_event_consumer: + # Remove our processor if it exists and add it to the end + if new_relic_event_consumer in processors: + processors.remove(new_relic_event_consumer) + processors.append(new_relic_event_consumer) return wrapped(*args, **kwargs) diff --git a/tests/logger_structlog/conftest.py b/tests/logger_structlog/conftest.py index 191d687c9c..825b9a8e75 100644 --- a/tests/logger_structlog/conftest.py +++ b/tests/logger_structlog/conftest.py @@ -12,7 +12,6 @@ # See the License for the specific language governing permissions and # limitations under the License. -import logging import pytest from newrelic.api.time_trace import current_trace from newrelic.api.transaction import current_transaction @@ -31,6 +30,7 @@ "application_logging.forwarding.enabled": True, "application_logging.metrics.enabled": True, "application_logging.local_decorating.enabled": True, + "application_logging.forwarding.context_data.enabled": True, "event_harvest_config.harvest_limits.log_event_data": 100000, } diff --git a/tests/logger_structlog/test_attribute_forwarding.py b/tests/logger_structlog/test_attribute_forwarding.py deleted file mode 100644 index eb555cca14..0000000000 --- a/tests/logger_structlog/test_attribute_forwarding.py +++ /dev/null @@ -1,49 +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 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 - - -_event_attributes = {"message": "A"} - - -@override_application_settings({ - "application_logging.forwarding.context_data.enabled": True, -}) -def test_attributes_inside_transaction(exercise_logging_single_line): - @validate_log_events([_event_attributes]) - @validate_log_event_count(1) - @background_task() - def test(): - exercise_logging_single_line() - - test() - - -@reset_core_stats_engine() -@override_application_settings({ - "application_logging.forwarding.context_data.enabled": True, -}) -def test_attributes_outside_transaction(exercise_logging_single_line): - @validate_log_events_outside_transaction([_event_attributes]) - @validate_log_event_count_outside_transaction(1) - def test(): - exercise_logging_single_line() - - test() diff --git a/tests/logger_structlog/test_attributes.py b/tests/logger_structlog/test_attributes.py new file mode 100644 index 0000000000..77e2da2171 --- /dev/null +++ b/tests/logger_structlog/test_attributes.py @@ -0,0 +1,98 @@ +# 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 testing_support.validators.validate_log_event_count import validate_log_event_count +from testing_support.validators.validate_log_events import validate_log_events + + +@pytest.fixture(scope="function") +def logger(structlog_caplog): + import structlog + + structlog.configure( + processors=[ + structlog.contextvars.merge_contextvars, + structlog.processors.format_exc_info, + structlog.processors.StackInfoRenderer(), + structlog.processors.CallsiteParameterAdder(), + ], + logger_factory=lambda *args, **kwargs: structlog_caplog, + ) + + _callsite_logger = structlog.get_logger(logger_attr=2) + structlog.contextvars.bind_contextvars(context_attr=3) + yield _callsite_logger + structlog.contextvars.clear_contextvars() + + +@validate_log_events( + [ + { # Fixed attributes + "message": "context_attrs: arg1", + "context.kwarg_attr": 1, + "context.logger_attr": 2, + "context.context_attr": 3, + "context.filename": "test_attributes.py", + "context.func_name": "test_structlog_default_context_attributes", + "context.module": "test_attributes", + "context.pathname": str(__file__), + "context.process_name": "MainProcess", + "context.thread_name": "MainThread", + } + ], + required_attrs=[ # Variable attributes + "context.lineno", + "context.process", + "context.thread", + ], +) +@validate_log_event_count(1) +@background_task() +def test_structlog_default_context_attributes(logger): + logger.error("context_attrs: %s", "arg1", kwarg_attr=1) + + +@validate_log_events([{"message": "exc_info"}], required_attrs=["context.exception"]) +@validate_log_event_count(1) +@background_task() +def test_structlog_exc_info_context_attributes(logger): + try: + raise RuntimeError("Oops") + except Exception: + logger.error("exc_info", exc_info=True) + + +@validate_log_events([{"message": "stack_info"}], required_attrs=["context.stack"]) +@validate_log_event_count(1) +@background_task() +def test_structlog_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_structlog_message_attributes(logger): + logger.error({"message": "A", "attr": 1}) + + +@validate_log_events([{"message.attr": 1}]) +@validate_log_event_count(1) +@background_task() +def test_structlog_attributes_only(logger): + logger.error({"attr": 1}) From bb3abf82465544b3933f8c10824ddf9d540be6cb Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Fri, 29 Dec 2023 15:52:47 -0800 Subject: [PATCH 15/22] Loguru instrumentation refactor --- newrelic/hooks/logger_loguru.py | 32 +++++++++++++++++++------------- 1 file changed, 19 insertions(+), 13 deletions(-) diff --git a/newrelic/hooks/logger_loguru.py b/newrelic/hooks/logger_loguru.py index 57427625c6..bb71acc94f 100644 --- a/newrelic/hooks/logger_loguru.py +++ b/newrelic/hooks/logger_loguru.py @@ -18,19 +18,25 @@ from newrelic.api.application import application_instance from newrelic.api.transaction import current_transaction, record_log_event from newrelic.common.object_wrapper import wrap_function_wrapper +from newrelic.common.package_version_utils import get_package_version_tuple from newrelic.common.signature import bind_args from newrelic.core.config import global_settings from newrelic.hooks.logger_logging import add_nr_linking_metadata -from newrelic.packages import six + _logger = logging.getLogger(__name__) -is_pypy = hasattr(sys, "pypy_version_info") +IS_PYPY = hasattr(sys, "pypy_version_info") +LOGURU_VERSION = get_package_version_tuple("loguru") +LOGURU_FILTERED_RECORD_ATTRS = {"extra", "message", "time", "level", "_nr_original_message", "record"} +ALLOWED_LOGURU_OPTIONS_LENGTHS = frozenset((8, 9)) -def loguru_version(): - from loguru import __version__ - return tuple(int(x) for x in __version__.split(".")) +def _filter_record_attributes(record): + attrs = {k: v for k, v in record.items() if k not in LOGURU_FILTERED_RECORD_ATTRS} + extra_attrs = dict(record.get("extra", {})) + attrs.update({"extra.%s" % k: v for k, v in extra_attrs.items()}) + return attrs def _nr_log_forwarder(message_instance): @@ -59,17 +65,17 @@ def _nr_log_forwarder(message_instance): application.record_custom_metric("Logging/lines/%s" % level_name, {"count": 1}) if settings.application_logging.forwarding and settings.application_logging.forwarding.enabled: - attrs = dict(record.get("extra", {})) + attrs = _filter_record_attributes(record) try: - record_log_event(message, level_name, int(record["time"].timestamp()), attributes=attrs) + time = record.get("time", None) + if time: + time = int(time.timestamp()) + record_log_event(message, level_name, time, attributes=attrs) except Exception: pass -ALLOWED_LOGURU_OPTIONS_LENGTHS = frozenset((8, 9)) - - def wrap_log(wrapped, instance, args, kwargs): try: bound_args = bind_args(wrapped, args, kwargs) @@ -80,7 +86,7 @@ def wrap_log(wrapped, instance, args, kwargs): # Loguru looks into the stack trace to find the caller's module and function names. # options[1] tells loguru how far up to look in the stack trace to find the caller. # Because wrap_log is an extra call in the stack trace, loguru needs to look 1 level higher. - if not is_pypy: + if not IS_PYPY: options[1] += 1 else: # PyPy inspection requires an additional frame of offset, as the wrapt internals seem to @@ -111,7 +117,7 @@ def _nr_log_patcher(record): record["_nr_original_message"] = message = record["message"] record["message"] = add_nr_linking_metadata(message) - if loguru_version() > (0, 6, 0): + if LOGURU_VERSION > (0, 6, 0): if original_patcher is not None: patchers = [p for p in original_patcher] # Consumer iterable into list so we can modify # Wipe out reference so patchers aren't called twice, as the framework will handle calling other patchers. @@ -137,7 +143,7 @@ def patch_loguru_logger(logger): logger.add(_nr_log_forwarder, format="{message}") logger._core._nr_instrumented = True elif not hasattr(logger, "_nr_instrumented"): # pragma: no cover - for _, handler in six.iteritems(logger._handlers): + for _, handler in logger._handlers.items(): if handler._writer is _nr_log_forwarder: logger._nr_instrumented = True return From 55a35b3c23473443ab760dd83520c54a31b314f3 Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Fri, 29 Dec 2023 15:54:55 -0800 Subject: [PATCH 16/22] New attribute testing --- tests/logger_loguru/conftest.py | 4 +- .../test_attribute_forwarding.py | 65 ----------------- tests/logger_loguru/test_attributes.py | 70 +++++++++++++++++++ 3 files changed, 73 insertions(+), 66 deletions(-) delete mode 100644 tests/logger_loguru/test_attribute_forwarding.py create mode 100644 tests/logger_loguru/test_attributes.py diff --git a/tests/logger_loguru/conftest.py b/tests/logger_loguru/conftest.py index 1be79f89b1..3239a6ff8e 100644 --- a/tests/logger_loguru/conftest.py +++ b/tests/logger_loguru/conftest.py @@ -30,6 +30,7 @@ "application_logging.forwarding.enabled": True, "application_logging.metrics.enabled": True, "application_logging.local_decorating.enabled": True, + "application_logging.forwarding.context_data.enabled": True, "event_harvest_config.harvest_limits.log_event_data": 100000, } @@ -58,7 +59,8 @@ def logger(): import loguru _logger = loguru.logger - _logger.configure(extra={"global_extra": "global_value"}) + _logger.configure(extra={"global_extra": 3}) + _logger = _logger.opt(exception=True, record=True) caplog = CaplogHandler() handler_id = _logger.add(caplog, level="WARNING", format="{message}") diff --git a/tests/logger_loguru/test_attribute_forwarding.py b/tests/logger_loguru/test_attribute_forwarding.py deleted file mode 100644 index d81608e3c6..0000000000 --- a/tests/logger_loguru/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.bind(key="value").error("A") - assert len(logger.caplog.records) == 1 - - -@override_application_settings( - { - "application_logging.forwarding.context_data.enabled": True, - } -) -def test_attributes_inside_transaction(logger): - @validate_log_events([_event_attributes]) - @validate_log_event_count(1) - @background_task() - def test(): - exercise_logging(logger) - - test() - - -@reset_core_stats_engine() -@override_application_settings( - { - "application_logging.forwarding.context_data.enabled": True, - } -) -def test_attributes_outside_transaction(logger): - @validate_log_events_outside_transaction([_event_attributes]) - @validate_log_event_count_outside_transaction(1) - def test(): - exercise_logging(logger) - - test() diff --git a/tests/logger_loguru/test_attributes.py b/tests/logger_loguru/test_attributes.py new file mode 100644 index 0000000000..9bba64f076 --- /dev/null +++ b/tests/logger_loguru/test_attributes.py @@ -0,0 +1,70 @@ +# Copyright 2010 New Relic, Inc. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +from newrelic.api.background_task import background_task + +from testing_support.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.file": "(name='%s', path='%s')" % ("test_attributes.py", str(__file__)), + "context.function": "test_loguru_default_context_attributes", + "context.extra.bound_attr": 1, + "context.extra.contextual_attr": 2, + "context.extra.global_extra": 3, + "context.extra.kwarg_attr": 4, + "context.patched_attr": 5, + "context.module": "test_attributes", + "context.name": "test_attributes", + } + ], + required_attrs=[ # Variable attributes + "context.elapsed", + "context.line", + "context.process", + "context.thread", + ], +) +@validate_log_event_count(1) +@background_task() +def test_loguru_default_context_attributes(logger): + def _patcher(d): + d["patched_attr"] = 5 + return d + + bound_logger = logger.bind(bound_attr=1) + bound_logger = bound_logger.patch(_patcher) + with bound_logger.contextualize(contextual_attr=2): + bound_logger.error("context_attrs: {}", "arg1", kwarg_attr=4) + + +@validate_log_events([{"message": "exc_info"}], required_attrs=["context.exception"]) +@validate_log_event_count(1) +@background_task() +def test_loguru_exc_info_context_attributes(logger): + try: + raise RuntimeError("Oops") + except Exception: + logger.error("exc_info") + + +@validate_log_events([{"context.extra.attr": 1}]) +@validate_log_event_count(1) +@background_task() +def test_loguru_attributes_only(logger): + logger.error("", attr=1) From 0a58f1e0fc4f1af2ccb9da7cb35a69c2ebb625ee Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Fri, 29 Dec 2023 16:01:46 -0800 Subject: [PATCH 17/22] Move exception settings --- tests/logger_loguru/conftest.py | 2 +- tests/logger_loguru/test_attributes.py | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/logger_loguru/conftest.py b/tests/logger_loguru/conftest.py index 3239a6ff8e..d87f7060d0 100644 --- a/tests/logger_loguru/conftest.py +++ b/tests/logger_loguru/conftest.py @@ -60,7 +60,7 @@ def logger(): _logger = loguru.logger _logger.configure(extra={"global_extra": 3}) - _logger = _logger.opt(exception=True, record=True) + _logger = _logger.opt(record=True) caplog = CaplogHandler() handler_id = _logger.add(caplog, level="WARNING", format="{message}") diff --git a/tests/logger_loguru/test_attributes.py b/tests/logger_loguru/test_attributes.py index 9bba64f076..ec7dc983d4 100644 --- a/tests/logger_loguru/test_attributes.py +++ b/tests/logger_loguru/test_attributes.py @@ -60,7 +60,7 @@ def test_loguru_exc_info_context_attributes(logger): try: raise RuntimeError("Oops") except Exception: - logger.error("exc_info") + logger.opt(exception=True).error("exc_info") @validate_log_events([{"context.extra.attr": 1}]) From dff566cc76fda156d29e6f6aa0b9dbde02b45609 Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Fri, 29 Dec 2023 16:05:13 -0800 Subject: [PATCH 18/22] Clean up testing --- tests/logger_loguru/test_attributes.py | 2 +- tests/logger_loguru/test_stack_inspection.py | 56 -------------------- 2 files changed, 1 insertion(+), 57 deletions(-) delete mode 100644 tests/logger_loguru/test_stack_inspection.py diff --git a/tests/logger_loguru/test_attributes.py b/tests/logger_loguru/test_attributes.py index ec7dc983d4..e764119a9d 100644 --- a/tests/logger_loguru/test_attributes.py +++ b/tests/logger_loguru/test_attributes.py @@ -56,7 +56,7 @@ def _patcher(d): @validate_log_events([{"message": "exc_info"}], required_attrs=["context.exception"]) @validate_log_event_count(1) @background_task() -def test_loguru_exc_info_context_attributes(logger): +def test_loguru_exception_context_attributes(logger): try: raise RuntimeError("Oops") except Exception: diff --git a/tests/logger_loguru/test_stack_inspection.py b/tests/logger_loguru/test_stack_inspection.py deleted file mode 100644 index fb2738ac2a..0000000000 --- a/tests/logger_loguru/test_stack_inspection.py +++ /dev/null @@ -1,56 +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 conftest import CaplogHandler - -from newrelic.api.background_task import background_task -from testing_support.fixtures import reset_core_stats_engine -from testing_support.validators.validate_log_event_count import validate_log_event_count -from testing_support.validators.validate_log_events import validate_log_events -from testing_support.fixtures import override_application_settings - - - -@pytest.fixture(scope="function") -def filepath_logger(): - import loguru - _logger = loguru.logger - caplog = CaplogHandler() - handler_id = _logger.add(caplog, level="WARNING", format="{file}:{function} - {message}") - _logger.caplog = caplog - yield _logger - del caplog.records[:] - _logger.remove(handler_id) - - -@override_application_settings({ - "application_logging.local_decorating.enabled": False, -}) -@reset_core_stats_engine() -def test_filepath_inspection(filepath_logger): - # Test for regression in stack inspection that caused log messages. - # See https://github.com/newrelic/newrelic-python-agent/issues/603 - - @validate_log_events([{"message": "A", "level": "ERROR"}]) - @validate_log_event_count(1) - @background_task() - def test(): - filepath_logger.error("A") - assert len(filepath_logger.caplog.records) == 1 - record = filepath_logger.caplog.records[0] - assert record == "test_stack_inspection.py:test - A", record - - test() From 860eb1317c24021e483c8df695461bb536161ee5 Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Fri, 29 Dec 2023 16:09:08 -0800 Subject: [PATCH 19/22] Remove unneeded option --- tests/logger_loguru/test_attributes.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/logger_loguru/test_attributes.py b/tests/logger_loguru/test_attributes.py index e764119a9d..44974d48b7 100644 --- a/tests/logger_loguru/test_attributes.py +++ b/tests/logger_loguru/test_attributes.py @@ -60,7 +60,7 @@ def test_loguru_exception_context_attributes(logger): try: raise RuntimeError("Oops") except Exception: - logger.opt(exception=True).error("exc_info") + logger.error("exc_info") @validate_log_events([{"context.extra.attr": 1}]) From e19c95b16a2d102db70a0dfe91df410d5c32e0cb Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Mon, 8 Jan 2024 12:26:11 -0800 Subject: [PATCH 20/22] Remove other framework changes --- newrelic/hooks/logger_logging.py | 24 ++--- newrelic/hooks/logger_structlog.py | 73 +++++--------- tests/agent_features/test_log_events.py | 2 + 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 +- tests/logger_structlog/conftest.py | 2 +- .../test_attribute_forwarding.py | 49 ++++++++++ tests/logger_structlog/test_attributes.py | 98 ------------------- 12 files changed, 180 insertions(+), 287 deletions(-) create mode 100644 tests/logger_logging/test_attribute_forwarding.py delete mode 100644 tests/logger_logging/test_attributes.py create mode 100644 tests/logger_structlog/test_attribute_forwarding.py delete mode 100644 tests/logger_structlog/test_attributes.py diff --git a/newrelic/hooks/logger_logging.py b/newrelic/hooks/logger_logging.py index 2d6ea2f4ed..80cf0fd248 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/newrelic/hooks/logger_structlog.py b/newrelic/hooks/logger_structlog.py index 1d6cf40af4..06d13aa4aa 100644 --- a/newrelic/hooks/logger_structlog.py +++ b/newrelic/hooks/logger_structlog.py @@ -12,17 +12,14 @@ # See the License for the specific language governing permissions and # limitations under the License. -import functools - -from newrelic.api.application import application_instance -from newrelic.api.transaction import current_transaction, record_log_event from newrelic.common.object_wrapper import wrap_function_wrapper -from newrelic.common.signature import bind_args +from newrelic.api.transaction import current_transaction, record_log_event from newrelic.core.config import global_settings +from newrelic.api.application import application_instance from newrelic.hooks.logger_logging import add_nr_linking_metadata +from newrelic.common.signature import bind_args -@functools.cache def normalize_level_name(method_name): # Look up level number for method name, using result to look up level name for that level number. # Convert result to upper case, and default to UNKNOWN in case of errors or missing values. @@ -37,7 +34,14 @@ def bind_process_event(method_name, event, event_kw): return method_name, event, event_kw -def new_relic_event_consumer(logger, level, event): +def wrap__process_event(wrapped, instance, args, kwargs): + try: + method_name, event, event_kw = bind_process_event(*args, **kwargs) + except TypeError: + return wrapped(*args, **kwargs) + + original_message = event # Save original undecorated message + transaction = current_transaction() if transaction: @@ -46,28 +50,16 @@ def new_relic_event_consumer(logger, level, event): settings = global_settings() # Return early if application logging not enabled - if settings and settings.application_logging.enabled: - if isinstance(event, (str, bytes, bytearray)): - message = original_message = event - event_attrs = {} - elif isinstance(event, dict): - message = original_message = event.get("event", "") - event_attrs = {k: v for k, v in event.items() if k != "event"} - else: - # Unclear how to proceed, ignore log. Avoid logging an error message or we may incur an infinite loop. - return event - - if settings.application_logging.local_decorating.enabled: - message = add_nr_linking_metadata(message) - if isinstance(event, (str, bytes, bytearray)): - event = message - elif isinstance(event, dict) and "event" in event: - # TODO CHECK ON THIS - event["event"] = message + if settings and settings.application_logging and settings.application_logging.enabled: + if settings.application_logging.local_decorating and settings.application_logging.local_decorating.enabled: + event = add_nr_linking_metadata(event) - level_name = normalize_level_name(level) + # Send log to processors for filtering, allowing any DropEvent exceptions that occur to prevent instrumentation from recording the log event. + result = wrapped(method_name, event, event_kw) + + level_name = normalize_level_name(method_name) - if settings.application_logging.metrics.enabled: + if settings.application_logging.metrics and settings.application_logging.metrics.enabled: if transaction: transaction.record_custom_metric("Logging/lines", {"count": 1}) transaction.record_custom_metric("Logging/lines/%s" % level_name, {"count": 1}) @@ -77,34 +69,15 @@ def new_relic_event_consumer(logger, level, event): application.record_custom_metric("Logging/lines", {"count": 1}) application.record_custom_metric("Logging/lines/%s" % level_name, {"count": 1}) - if settings.application_logging.forwarding.enabled: + if settings.application_logging.forwarding and settings.application_logging.forwarding.enabled: try: - record_log_event(original_message, level_name, attributes=event_attrs) + record_log_event(original_message, level_name) except Exception: pass - return event - - -def wrap__process_event(wrapped, instance, args, kwargs): - transaction = current_transaction() - - if transaction: - settings = transaction.settings - else: - settings = global_settings() - - # Return early if application logging not enabled - if settings and settings.application_logging and settings.application_logging.enabled: - processors = instance._processors - if not processors: - instance._processors = [new_relic_event_consumer] - elif processors[-1] != new_relic_event_consumer: - # Remove our processor if it exists and add it to the end - if new_relic_event_consumer in processors: - processors.remove(new_relic_event_consumer) - processors.append(new_relic_event_consumer) + # Return the result from wrapped after we've recorded the resulting log event. + return result return wrapped(*args, **kwargs) diff --git a/tests/agent_features/test_log_events.py b/tests/agent_features/test_log_events.py index e760d0acb1..fb9991a823 100644 --- a/tests/agent_features/test_log_events.py +++ b/tests/agent_features/test_log_events.py @@ -291,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): @@ -379,6 +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, diff --git a/tests/logger_logging/conftest.py b/tests/logger_logging/conftest.py index b9ecf85265..46e8f4ec3a 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 0000000000..eea549e709 --- /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 f125b84268..0000000000 --- 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 7b420375cb..d4917eff59 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 67b5404562..ee6c689b76 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 8a892624e8..dce99f9f8e 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(): diff --git a/tests/logger_structlog/conftest.py b/tests/logger_structlog/conftest.py index 825b9a8e75..191d687c9c 100644 --- a/tests/logger_structlog/conftest.py +++ b/tests/logger_structlog/conftest.py @@ -12,6 +12,7 @@ # See the License for the specific language governing permissions and # limitations under the License. +import logging import pytest from newrelic.api.time_trace import current_trace from newrelic.api.transaction import current_transaction @@ -30,7 +31,6 @@ "application_logging.forwarding.enabled": True, "application_logging.metrics.enabled": True, "application_logging.local_decorating.enabled": True, - "application_logging.forwarding.context_data.enabled": True, "event_harvest_config.harvest_limits.log_event_data": 100000, } diff --git a/tests/logger_structlog/test_attribute_forwarding.py b/tests/logger_structlog/test_attribute_forwarding.py new file mode 100644 index 0000000000..eb555cca14 --- /dev/null +++ b/tests/logger_structlog/test_attribute_forwarding.py @@ -0,0 +1,49 @@ +# Copyright 2010 New Relic, Inc. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +from newrelic.api.background_task import background_task +from testing_support.fixtures import 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 + + +_event_attributes = {"message": "A"} + + +@override_application_settings({ + "application_logging.forwarding.context_data.enabled": True, +}) +def test_attributes_inside_transaction(exercise_logging_single_line): + @validate_log_events([_event_attributes]) + @validate_log_event_count(1) + @background_task() + def test(): + exercise_logging_single_line() + + test() + + +@reset_core_stats_engine() +@override_application_settings({ + "application_logging.forwarding.context_data.enabled": True, +}) +def test_attributes_outside_transaction(exercise_logging_single_line): + @validate_log_events_outside_transaction([_event_attributes]) + @validate_log_event_count_outside_transaction(1) + def test(): + exercise_logging_single_line() + + test() diff --git a/tests/logger_structlog/test_attributes.py b/tests/logger_structlog/test_attributes.py deleted file mode 100644 index 77e2da2171..0000000000 --- a/tests/logger_structlog/test_attributes.py +++ /dev/null @@ -1,98 +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 testing_support.validators.validate_log_event_count import validate_log_event_count -from testing_support.validators.validate_log_events import validate_log_events - - -@pytest.fixture(scope="function") -def logger(structlog_caplog): - import structlog - - structlog.configure( - processors=[ - structlog.contextvars.merge_contextvars, - structlog.processors.format_exc_info, - structlog.processors.StackInfoRenderer(), - structlog.processors.CallsiteParameterAdder(), - ], - logger_factory=lambda *args, **kwargs: structlog_caplog, - ) - - _callsite_logger = structlog.get_logger(logger_attr=2) - structlog.contextvars.bind_contextvars(context_attr=3) - yield _callsite_logger - structlog.contextvars.clear_contextvars() - - -@validate_log_events( - [ - { # Fixed attributes - "message": "context_attrs: arg1", - "context.kwarg_attr": 1, - "context.logger_attr": 2, - "context.context_attr": 3, - "context.filename": "test_attributes.py", - "context.func_name": "test_structlog_default_context_attributes", - "context.module": "test_attributes", - "context.pathname": str(__file__), - "context.process_name": "MainProcess", - "context.thread_name": "MainThread", - } - ], - required_attrs=[ # Variable attributes - "context.lineno", - "context.process", - "context.thread", - ], -) -@validate_log_event_count(1) -@background_task() -def test_structlog_default_context_attributes(logger): - logger.error("context_attrs: %s", "arg1", kwarg_attr=1) - - -@validate_log_events([{"message": "exc_info"}], required_attrs=["context.exception"]) -@validate_log_event_count(1) -@background_task() -def test_structlog_exc_info_context_attributes(logger): - try: - raise RuntimeError("Oops") - except Exception: - logger.error("exc_info", exc_info=True) - - -@validate_log_events([{"message": "stack_info"}], required_attrs=["context.stack"]) -@validate_log_event_count(1) -@background_task() -def test_structlog_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_structlog_message_attributes(logger): - logger.error({"message": "A", "attr": 1}) - - -@validate_log_events([{"message.attr": 1}]) -@validate_log_event_count(1) -@background_task() -def test_structlog_attributes_only(logger): - logger.error({"attr": 1}) From a8ef21aa793a623744cee08f6bae777b0ab2d7c5 Mon Sep 17 00:00:00 2001 From: TimPansino Date: Mon, 8 Jan 2024 20:36:31 +0000 Subject: [PATCH 21/22] [Mega-Linter] Apply linters fixes --- newrelic/hooks/logger_loguru.py | 1 - tests/logger_loguru/test_attributes.py | 4 ++-- 2 files changed, 2 insertions(+), 3 deletions(-) diff --git a/newrelic/hooks/logger_loguru.py b/newrelic/hooks/logger_loguru.py index bb71acc94f..2676859072 100644 --- a/newrelic/hooks/logger_loguru.py +++ b/newrelic/hooks/logger_loguru.py @@ -23,7 +23,6 @@ from newrelic.core.config import global_settings from newrelic.hooks.logger_logging import add_nr_linking_metadata - _logger = logging.getLogger(__name__) IS_PYPY = hasattr(sys, "pypy_version_info") diff --git a/tests/logger_loguru/test_attributes.py b/tests/logger_loguru/test_attributes.py index 44974d48b7..ff8151e0bd 100644 --- a/tests/logger_loguru/test_attributes.py +++ b/tests/logger_loguru/test_attributes.py @@ -12,11 +12,11 @@ # See the License for the specific language governing permissions and # limitations under the License. -from newrelic.api.background_task import background_task - from testing_support.validators.validate_log_event_count import validate_log_event_count from testing_support.validators.validate_log_events import validate_log_events +from newrelic.api.background_task import background_task + @validate_log_events( [ From 3d33f45da8c02dcf4bad9ce728690ab00f15830b Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Mon, 8 Jan 2024 12:38:43 -0800 Subject: [PATCH 22/22] Bump tests