From 7cc3ef31790243d39a6793ea1bcec2146e35ca9b Mon Sep 17 00:00:00 2001 From: fritzdj Date: Tue, 25 Jun 2024 08:47:00 -0400 Subject: [PATCH 1/7] NewRelicContextFormatter update to support adding a stack trace --- newrelic/api/log.py | 65 ++++++++++++++++++++++++++++++--------------- 1 file changed, 43 insertions(+), 22 deletions(-) diff --git a/newrelic/api/log.py b/newrelic/api/log.py index 8a33534b70..29128cdef2 100644 --- a/newrelic/api/log.py +++ b/newrelic/api/log.py @@ -16,6 +16,8 @@ import logging import re import warnings +from traceback import format_tb +from typing import Optional from newrelic.api.application import application_instance from newrelic.api.time_trace import get_linking_metadata @@ -28,22 +30,6 @@ from newrelic.packages import six -def format_exc_info(exc_info): - _, _, fullnames, message = parse_exc_info(exc_info) - fullname = fullnames[0] - - formatted = { - "error.class": fullname, - "error.message": message, - } - - expected = is_expected_error(exc_info) - if expected is not None: - formatted["error.expected"] = expected - - return formatted - - def safe_json_encode(obj, ignore_string_types=False, **kwargs): # Performs the same operation as json_encode but replaces unserializable objects with a string containing their class name. # If ignore_string_types is True, do not encode string types further. @@ -69,11 +55,46 @@ def safe_json_encode(obj, ignore_string_types=False, **kwargs): class NewRelicContextFormatter(logging.Formatter): DEFAULT_LOG_RECORD_KEYS = frozenset(set(vars(logging.LogRecord("", 0, "", 0, "", (), None))) | {"message"}) - def __init__(self, *args, **kwargs): - super(NewRelicContextFormatter, self).__init__() + def __init__(self, *args, stack_trace_limit: Optional[int] = 0, **kwargs): + """ + :param Optional[int] stack_trace_limit: + Specifies the maximum number of frames to include for stack traces. + Defaults to `0` to suppress stack traces. + Setting this to `None` will make it so all available frames are included. + """ + super(NewRelicContextFormatter, self).__init__(*args, **kwargs) + + if stack_trace_limit is not None: + if not isinstance(stack_trace_limit, int): + raise TypeError("stack_trace_limit must be None or a non-negative integer") + elif stack_trace_limit < 0: + raise ValueError("stack_trace_limit must be None or a non-negative integer") + self._stack_trace_limit = stack_trace_limit + + def format_exc_info(self, exc_info): + _, _, fullnames, message = parse_exc_info(exc_info) + fullname = fullnames[0] + + formatted = { + "error.class": fullname, + "error.message": message, + } - @classmethod - def log_record_to_dict(cls, record): + expected = is_expected_error(exc_info) + if expected is not None: + formatted["error.expected"] = expected + + if self._stack_trace_limit is None or self._stack_trace_limit > 0: + stack_trace: Optional[str] + if exc_info[2] is not None: + stack_trace = "".join(format_tb(exc_info[2], limit=self._stack_trace_limit)) or None + else: + stack_trace = None + formatted["error.stack_trace"] = stack_trace + + return formatted + + def log_record_to_dict(self, record): output = { "timestamp": int(record.created * 1000), "message": record.getMessage(), @@ -88,7 +109,7 @@ def log_record_to_dict(cls, record): } output.update(get_linking_metadata()) - DEFAULT_LOG_RECORD_KEYS = cls.DEFAULT_LOG_RECORD_KEYS + DEFAULT_LOG_RECORD_KEYS = self.DEFAULT_LOG_RECORD_KEYS # If any keys are present in record that aren't in the default, # add them to the output record. keys_to_add = set(record.__dict__.keys()) - DEFAULT_LOG_RECORD_KEYS @@ -96,7 +117,7 @@ def log_record_to_dict(cls, record): output["extra." + key] = getattr(record, key) if record.exc_info: - output.update(format_exc_info(record.exc_info)) + output.update(self.format_exc_info(record.exc_info)) return output From 03b7c20547fe995378dbfd9a025a72493fca1cdd Mon Sep 17 00:00:00 2001 From: fritzdj Date: Tue, 25 Jun 2024 09:12:44 -0400 Subject: [PATCH 2/7] Adding test coverage --- tests/agent_features/test_logs_in_context.py | 119 ++++++++++++++++++- 1 file changed, 117 insertions(+), 2 deletions(-) diff --git a/tests/agent_features/test_logs_in_context.py b/tests/agent_features/test_logs_in_context.py index 8f97ee226f..b208dc8143 100644 --- a/tests/agent_features/test_logs_in_context.py +++ b/tests/agent_features/test_logs_in_context.py @@ -14,6 +14,7 @@ import json import logging +from traceback import format_tb import pytest @@ -47,6 +48,22 @@ def log_buffer(caplog): _logger.removeHandler(_handler) +@pytest.fixture +def log_buffer_with_stack_trace(caplog): + buf = Buffer() + + _formatter = NewRelicContextFormatter("", datefmt="ISO8601", stack_trace_limit=None) + _handler = logging.StreamHandler(buf) + _handler.setFormatter(_formatter) + + _logger.addHandler(_handler) + caplog.set_level(logging.INFO, logger=__name__) + + yield buf + + _logger.removeHandler(_handler) + + class NonPrintableObject(object): def __str__(self): raise RuntimeError("Unable to print object.") @@ -174,7 +191,7 @@ class ExceptionForTest(ValueError): @background_task() -def test_newrelic_logger_error_inside_transaction(log_buffer): +def test_newrelic_logger_error_inside_transaction_no_stack_trace(log_buffer): try: raise ExceptionForTest except ExceptionForTest: @@ -220,7 +237,58 @@ def test_newrelic_logger_error_inside_transaction(log_buffer): assert set(message.keys()) == set(expected_extra_txn_keys) -def test_newrelic_logger_error_outside_transaction(log_buffer): +@background_task() +def test_newrelic_logger_error_inside_transaction_with_stack_trace(log_buffer_with_stack_trace): + try: + raise ExceptionForTest + except ExceptionForTest as e: + _logger.exception("oops") + expected_stack_trace = "".join(format_tb(e.__traceback__)) + + log_buffer_with_stack_trace.seek(0) + message = json.load(log_buffer_with_stack_trace) + + timestamp = message.pop("timestamp") + thread_id = message.pop("thread.id") + process_id = message.pop("process.id") + filename = message.pop("file.name") + line_number = message.pop("line.number") + stack_trace = message.pop("error.stack_trace") + + assert isinstance(timestamp, int) + assert isinstance(thread_id, int) + assert isinstance(process_id, int) + assert filename.endswith("/test_logs_in_context.py") + assert isinstance(line_number, int) + assert isinstance(stack_trace, str) + assert stack_trace == expected_stack_trace + + expected = { + "entity.name": "Python Agent Test (agent_features)", + "entity.type": "SERVICE", + "message": "oops", + "log.level": "ERROR", + "logger.name": "test_logs_in_context", + "thread.name": "MainThread", + "process.name": "MainProcess", + "error.class": "test_logs_in_context:ExceptionForTest", + "error.message": "", + "error.expected": False + } + expected_extra_txn_keys = ( + "trace.id", + "span.id", + "entity.guid", + "hostname" + ) + + for k, v in expected.items(): + assert message.pop(k) == v + + assert set(message.keys()) == set(expected_extra_txn_keys) + + +def test_newrelic_logger_error_outside_transaction_no_stack_trace(log_buffer): try: raise ExceptionForTest except ExceptionForTest: @@ -263,6 +331,53 @@ def test_newrelic_logger_error_outside_transaction(log_buffer): assert set(message.keys()) == set(expected_extra_txn_keys) +def test_newrelic_logger_error_outside_transaction_with_stack_trace(log_buffer_with_stack_trace): + try: + raise ExceptionForTest + except ExceptionForTest as e: + _logger.exception("oops") + expected_stack_trace = "".join(format_tb(e.__traceback__)) + + log_buffer_with_stack_trace.seek(0) + message = json.load(log_buffer_with_stack_trace) + + timestamp = message.pop("timestamp") + thread_id = message.pop("thread.id") + process_id = message.pop("process.id") + filename = message.pop("file.name") + line_number = message.pop("line.number") + stack_trace = message.pop("error.stack_trace") + + assert isinstance(timestamp, int) + assert isinstance(thread_id, int) + assert isinstance(process_id, int) + assert filename.endswith("/test_logs_in_context.py") + assert isinstance(line_number, int) + assert isinstance(stack_trace, str) + assert stack_trace == expected_stack_trace + + expected = { + "entity.name": "Python Agent Test (agent_features)", + "entity.type": "SERVICE", + "message": "oops", + "log.level": "ERROR", + "logger.name": "test_logs_in_context", + "thread.name": "MainThread", + "process.name": "MainProcess", + "error.class": "test_logs_in_context:ExceptionForTest", + "error.message": "", + } + expected_extra_txn_keys = ( + "entity.guid", + "hostname", + ) + + for k, v in expected.items(): + assert message.pop(k) == v + + assert set(message.keys()) == set(expected_extra_txn_keys) + + EXPECTED_KEYS_TXN = ( "trace.id", "span.id", From 5aa8883c2d7023fc20e1754b1f3fcf9c28d4a1d5 Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Thu, 27 Jun 2024 11:19:30 -0700 Subject: [PATCH 3/7] Remove typing for Python 2 compatibility --- newrelic/api/log.py | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/newrelic/api/log.py b/newrelic/api/log.py index 29128cdef2..8f1eaa0cf3 100644 --- a/newrelic/api/log.py +++ b/newrelic/api/log.py @@ -17,7 +17,6 @@ import re import warnings from traceback import format_tb -from typing import Optional from newrelic.api.application import application_instance from newrelic.api.time_trace import get_linking_metadata @@ -55,7 +54,7 @@ def safe_json_encode(obj, ignore_string_types=False, **kwargs): class NewRelicContextFormatter(logging.Formatter): DEFAULT_LOG_RECORD_KEYS = frozenset(set(vars(logging.LogRecord("", 0, "", 0, "", (), None))) | {"message"}) - def __init__(self, *args, stack_trace_limit: Optional[int] = 0, **kwargs): + def __init__(self, *args, stack_trace_limit=0, **kwargs): """ :param Optional[int] stack_trace_limit: Specifies the maximum number of frames to include for stack traces. @@ -85,7 +84,6 @@ def format_exc_info(self, exc_info): formatted["error.expected"] = expected if self._stack_trace_limit is None or self._stack_trace_limit > 0: - stack_trace: Optional[str] if exc_info[2] is not None: stack_trace = "".join(format_tb(exc_info[2], limit=self._stack_trace_limit)) or None else: From f4a84a5ea5f484b04450aa98f7d551b3cc2acae5 Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Thu, 27 Jun 2024 11:20:07 -0700 Subject: [PATCH 4/7] Refactor instance methods to class methods and export --- newrelic/api/log.py | 21 ++++++++++++++------- 1 file changed, 14 insertions(+), 7 deletions(-) diff --git a/newrelic/api/log.py b/newrelic/api/log.py index 8f1eaa0cf3..3cdee80450 100644 --- a/newrelic/api/log.py +++ b/newrelic/api/log.py @@ -70,7 +70,8 @@ def __init__(self, *args, stack_trace_limit=0, **kwargs): raise ValueError("stack_trace_limit must be None or a non-negative integer") self._stack_trace_limit = stack_trace_limit - def format_exc_info(self, exc_info): + @classmethod + def format_exc_info(cls, exc_info, stack_trace_limit=0): _, _, fullnames, message = parse_exc_info(exc_info) fullname = fullnames[0] @@ -83,16 +84,17 @@ def format_exc_info(self, exc_info): if expected is not None: formatted["error.expected"] = expected - if self._stack_trace_limit is None or self._stack_trace_limit > 0: + if stack_trace_limit is None or stack_trace_limit > 0: if exc_info[2] is not None: - stack_trace = "".join(format_tb(exc_info[2], limit=self._stack_trace_limit)) or None + stack_trace = "".join(format_tb(exc_info[2], limit=stack_trace_limit)) or None else: stack_trace = None formatted["error.stack_trace"] = stack_trace return formatted - def log_record_to_dict(self, record): + @classmethod + def log_record_to_dict(cls, record, stack_trace_limit=0): output = { "timestamp": int(record.created * 1000), "message": record.getMessage(), @@ -107,7 +109,7 @@ def log_record_to_dict(self, record): } output.update(get_linking_metadata()) - DEFAULT_LOG_RECORD_KEYS = self.DEFAULT_LOG_RECORD_KEYS + DEFAULT_LOG_RECORD_KEYS = cls.DEFAULT_LOG_RECORD_KEYS # If any keys are present in record that aren't in the default, # add them to the output record. keys_to_add = set(record.__dict__.keys()) - DEFAULT_LOG_RECORD_KEYS @@ -115,12 +117,17 @@ def log_record_to_dict(self, record): output["extra." + key] = getattr(record, key) if record.exc_info: - output.update(self.format_exc_info(record.exc_info)) + output.update(cls.format_exc_info(record.exc_info, stack_trace_limit)) return output def format(self, record): - return json.dumps(self.log_record_to_dict(record), default=safe_json_encode, separators=(",", ":")) + return json.dumps(self.log_record_to_dict(record, self._stack_trace_limit), default=safe_json_encode, separators=(",", ":")) + + +# Export class methods as top level functions for compatibility +log_record_to_dict = NewRelicContextFormatter.log_record_to_dict +format_exc_info = NewRelicContextFormatter.format_exc_info class NewRelicLogForwardingHandler(logging.Handler): From 2faa80f30003c746048dcf4a0db529dbdeb5a7f3 Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Thu, 27 Jun 2024 11:20:28 -0700 Subject: [PATCH 5/7] Add truthy safeguard to log tests --- tests/agent_features/test_logs_in_context.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/agent_features/test_logs_in_context.py b/tests/agent_features/test_logs_in_context.py index b208dc8143..1addfca6b1 100644 --- a/tests/agent_features/test_logs_in_context.py +++ b/tests/agent_features/test_logs_in_context.py @@ -261,7 +261,7 @@ def test_newrelic_logger_error_inside_transaction_with_stack_trace(log_buffer_wi assert filename.endswith("/test_logs_in_context.py") assert isinstance(line_number, int) assert isinstance(stack_trace, str) - assert stack_trace == expected_stack_trace + assert stack_trace and stack_trace == expected_stack_trace expected = { "entity.name": "Python Agent Test (agent_features)", @@ -354,7 +354,7 @@ def test_newrelic_logger_error_outside_transaction_with_stack_trace(log_buffer_w assert filename.endswith("/test_logs_in_context.py") assert isinstance(line_number, int) assert isinstance(stack_trace, str) - assert stack_trace == expected_stack_trace + assert stack_trace and stack_trace == expected_stack_trace expected = { "entity.name": "Python Agent Test (agent_features)", From 4d594e575244e41168544477f6ed6c060194f5b0 Mon Sep 17 00:00:00 2001 From: Tim Pansino Date: Thu, 27 Jun 2024 11:31:15 -0700 Subject: [PATCH 6/7] Fix Python 2 issues in tests --- newrelic/api/log.py | 6 ++++-- tests/agent_features/test_logs_in_context.py | 13 +++++++------ 2 files changed, 11 insertions(+), 8 deletions(-) diff --git a/newrelic/api/log.py b/newrelic/api/log.py index 3cdee80450..4e5e43f279 100644 --- a/newrelic/api/log.py +++ b/newrelic/api/log.py @@ -54,14 +54,14 @@ def safe_json_encode(obj, ignore_string_types=False, **kwargs): class NewRelicContextFormatter(logging.Formatter): DEFAULT_LOG_RECORD_KEYS = frozenset(set(vars(logging.LogRecord("", 0, "", 0, "", (), None))) | {"message"}) - def __init__(self, *args, stack_trace_limit=0, **kwargs): + def __init__(self, *args, **kwargs): """ :param Optional[int] stack_trace_limit: Specifies the maximum number of frames to include for stack traces. Defaults to `0` to suppress stack traces. Setting this to `None` will make it so all available frames are included. """ - super(NewRelicContextFormatter, self).__init__(*args, **kwargs) + stack_trace_limit = kwargs.pop("stack_trace_limit", 0) if stack_trace_limit is not None: if not isinstance(stack_trace_limit, int): @@ -70,6 +70,8 @@ def __init__(self, *args, stack_trace_limit=0, **kwargs): raise ValueError("stack_trace_limit must be None or a non-negative integer") self._stack_trace_limit = stack_trace_limit + super(NewRelicContextFormatter, self).__init__(*args, **kwargs) + @classmethod def format_exc_info(cls, exc_info, stack_trace_limit=0): _, _, fullnames, message = parse_exc_info(exc_info) diff --git a/tests/agent_features/test_logs_in_context.py b/tests/agent_features/test_logs_in_context.py index 1addfca6b1..05f2504350 100644 --- a/tests/agent_features/test_logs_in_context.py +++ b/tests/agent_features/test_logs_in_context.py @@ -14,6 +14,7 @@ import json import logging +import sys from traceback import format_tb import pytest @@ -241,9 +242,9 @@ def test_newrelic_logger_error_inside_transaction_no_stack_trace(log_buffer): def test_newrelic_logger_error_inside_transaction_with_stack_trace(log_buffer_with_stack_trace): try: raise ExceptionForTest - except ExceptionForTest as e: + except ExceptionForTest: _logger.exception("oops") - expected_stack_trace = "".join(format_tb(e.__traceback__)) + expected_stack_trace = "".join(format_tb(sys.exc_info()[2])) log_buffer_with_stack_trace.seek(0) message = json.load(log_buffer_with_stack_trace) @@ -260,7 +261,7 @@ def test_newrelic_logger_error_inside_transaction_with_stack_trace(log_buffer_wi assert isinstance(process_id, int) assert filename.endswith("/test_logs_in_context.py") assert isinstance(line_number, int) - assert isinstance(stack_trace, str) + assert isinstance(stack_trace, six.string_types) assert stack_trace and stack_trace == expected_stack_trace expected = { @@ -334,9 +335,9 @@ def test_newrelic_logger_error_outside_transaction_no_stack_trace(log_buffer): def test_newrelic_logger_error_outside_transaction_with_stack_trace(log_buffer_with_stack_trace): try: raise ExceptionForTest - except ExceptionForTest as e: + except ExceptionForTest: _logger.exception("oops") - expected_stack_trace = "".join(format_tb(e.__traceback__)) + expected_stack_trace = "".join(format_tb(sys.exc_info()[2])) log_buffer_with_stack_trace.seek(0) message = json.load(log_buffer_with_stack_trace) @@ -353,7 +354,7 @@ def test_newrelic_logger_error_outside_transaction_with_stack_trace(log_buffer_w assert isinstance(process_id, int) assert filename.endswith("/test_logs_in_context.py") assert isinstance(line_number, int) - assert isinstance(stack_trace, str) + assert isinstance(stack_trace, six.string_types) assert stack_trace and stack_trace == expected_stack_trace expected = { From 817e97a5df908d39419cade3f6d68ecd90ac5f35 Mon Sep 17 00:00:00 2001 From: fritzdj Date: Mon, 8 Jul 2024 14:11:24 -0400 Subject: [PATCH 7/7] lint:fix --- newrelic/api/log.py | 2 +- tests/agent_features/test_logs_in_context.py | 2 ++ 2 files changed, 3 insertions(+), 1 deletion(-) diff --git a/newrelic/api/log.py b/newrelic/api/log.py index 4e5e43f279..9edd40e2e1 100644 --- a/newrelic/api/log.py +++ b/newrelic/api/log.py @@ -66,7 +66,7 @@ def __init__(self, *args, **kwargs): if stack_trace_limit is not None: if not isinstance(stack_trace_limit, int): raise TypeError("stack_trace_limit must be None or a non-negative integer") - elif stack_trace_limit < 0: + if stack_trace_limit < 0: raise ValueError("stack_trace_limit must be None or a non-negative integer") self._stack_trace_limit = stack_trace_limit diff --git a/tests/agent_features/test_logs_in_context.py b/tests/agent_features/test_logs_in_context.py index 05f2504350..c4f7bcd21d 100644 --- a/tests/agent_features/test_logs_in_context.py +++ b/tests/agent_features/test_logs_in_context.py @@ -240,6 +240,7 @@ def test_newrelic_logger_error_inside_transaction_no_stack_trace(log_buffer): @background_task() def test_newrelic_logger_error_inside_transaction_with_stack_trace(log_buffer_with_stack_trace): + expected_stack_trace = "" try: raise ExceptionForTest except ExceptionForTest: @@ -333,6 +334,7 @@ def test_newrelic_logger_error_outside_transaction_no_stack_trace(log_buffer): def test_newrelic_logger_error_outside_transaction_with_stack_trace(log_buffer_with_stack_trace): + expected_stack_trace = "" try: raise ExceptionForTest except ExceptionForTest: