From b004eadb58fe0c6feace8c5c00cafef557cb6b68 Mon Sep 17 00:00:00 2001 From: Timothy Pansino <11214426+TimPansino@users.noreply.github.com> Date: Fri, 3 Jun 2022 11:26:11 -0700 Subject: [PATCH] Loguru Instrumentation (#552) * Add loguru instrumentation * Add more loguru versions to test * Correct tox ini file * Fix missing parenthesis * Fix loguru v4 and add patching test * Patch loguru v3 support --- newrelic/config.py | 11 ++ newrelic/hooks/logger_loguru.py | 142 +++++++++++++++++++ tests/logger_loguru/conftest.py | 71 ++++++++++ tests/logger_loguru/test_local_decorating.py | 88 ++++++++++++ tests/logger_loguru/test_log_forwarding.py | 94 ++++++++++++ tests/logger_loguru/test_metrics.py | 61 ++++++++ tests/logger_loguru/test_settings.py | 109 ++++++++++++++ tox.ini | 10 +- 8 files changed, 585 insertions(+), 1 deletion(-) create mode 100644 newrelic/hooks/logger_loguru.py create mode 100644 tests/logger_loguru/conftest.py create mode 100644 tests/logger_loguru/test_local_decorating.py create mode 100644 tests/logger_loguru/test_log_forwarding.py create mode 100644 tests/logger_loguru/test_metrics.py create mode 100644 tests/logger_loguru/test_settings.py diff --git a/newrelic/config.py b/newrelic/config.py index 29b5ba1fa1..11601551c2 100644 --- a/newrelic/config.py +++ b/newrelic/config.py @@ -2313,6 +2313,17 @@ def _process_module_builtin_defaults(): "instrument_logging", ) + _process_module_definition( + "loguru", + "newrelic.hooks.logger_loguru", + "instrument_loguru", + ) + _process_module_definition( + "loguru._logger", + "newrelic.hooks.logger_loguru", + "instrument_loguru_logger", + ) + _process_module_definition( "paste.httpserver", "newrelic.hooks.adapter_paste", diff --git a/newrelic/hooks/logger_loguru.py b/newrelic/hooks/logger_loguru.py new file mode 100644 index 0000000000..65eadb1c46 --- /dev/null +++ b/newrelic/hooks/logger_loguru.py @@ -0,0 +1,142 @@ +# 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 logging + +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.core.config import global_settings +from newrelic.hooks.logger_logging import add_nr_linking_metadata +from newrelic.packages import six + +_logger = logging.getLogger(__name__) + +def loguru_version(): + from loguru import __version__ + return tuple(int(x) for x in __version__.split(".")) + + +def _nr_log_forwarder(message_instance): + transaction = current_transaction() + record = message_instance.record + message = record.get("_nr_original_message", record["message"]) + + 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: + level = record["level"] + level_name = "UNKNOWN" if not level else (level.name or "UNKNOWN") + + 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}) + else: + application = application_instance(activate=False) + if application and application.enabled: + 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: + try: + record_log_event(message, level_name, int(record["time"].timestamp())) + except Exception: + pass + + +ALLOWED_LOGURU_OPTIONS_LENGTHS = frozenset((8, 9)) + +def bind_log(level_id, static_level_no, from_decorator, options, message, args, kwargs): + assert len(options) in ALLOWED_LOGURU_OPTIONS_LENGTHS # Assert the options signature we expect + return level_id, static_level_no, from_decorator, list(options), message, args, kwargs + + +def wrap_log(wrapped, instance, args, kwargs): + try: + level_id, static_level_no, from_decorator, options, message, subargs, subkwargs = bind_log(*args, **kwargs) + options[-2] = nr_log_patcher(options[-2]) + except Exception as e: + _logger.debug("Exception in loguru handling: %s" % str(e)) + return wrapped(*args, **kwargs) + else: + return wrapped(level_id, static_level_no, from_decorator, options, message, subargs, subkwargs) + + +def nr_log_patcher(original_patcher=None): + def _nr_log_patcher(record): + if original_patcher: + record = original_patcher(record) + + transaction = current_transaction() + + if transaction: + settings = transaction.settings + else: + settings = global_settings() + + if settings and settings.application_logging and settings.application_logging.enabled: + if settings.application_logging.local_decorating and settings.application_logging.local_decorating.enabled: + record["_nr_original_message"] = message = record["message"] + record["message"] = add_nr_linking_metadata(message) + + 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. + original_patcher = None + else: + patchers = [] + + patchers.append(_nr_log_patcher) + return patchers + else: + return _nr_log_patcher + + +def wrap_Logger_init(wrapped, instance, args, kwargs): + result = wrapped(*args, **kwargs) + patch_loguru_logger(instance) + return result + + +def patch_loguru_logger(logger): + if hasattr(logger, "_core"): + if not hasattr(logger._core, "_nr_instrumented"): + logger.add(_nr_log_forwarder, format="{message}") + logger._core._nr_instrumented = True + elif not hasattr(logger, "_nr_instrumented"): + for _, handler in six.iteritems(logger._handlers): + if handler._writer is _nr_log_forwarder: + logger._nr_instrumented = True + return + + logger.add(_nr_log_forwarder, format="{message}") + logger._nr_instrumented = True + + +def instrument_loguru_logger(module): + if hasattr(module, "Logger"): + wrap_function_wrapper(module, "Logger.__init__", wrap_Logger_init) + if hasattr(module.Logger, "_log"): + wrap_function_wrapper(module, "Logger._log", wrap_log) + + +def instrument_loguru(module): + if hasattr(module, "logger"): + patch_loguru_logger(module.logger) diff --git a/tests/logger_loguru/conftest.py b/tests/logger_loguru/conftest.py new file mode 100644 index 0000000000..af632e3004 --- /dev/null +++ b/tests/logger_loguru/conftest.py @@ -0,0 +1,71 @@ +# 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 logging +import pytest + +from testing_support.fixtures import ( + code_coverage_fixture, + collector_agent_registration_fixture, + collector_available_fixture, +) + +_coverage_source = [ + "newrelic.hooks.logger_loguru", +] + +code_coverage = code_coverage_fixture(source=_coverage_source) + +_default_settings = { + "transaction_tracer.explain_threshold": 0.0, + "transaction_tracer.transaction_threshold": 0.0, + "transaction_tracer.stack_trace_threshold": 0.0, + "debug.log_data_collector_payloads": True, + "debug.record_transaction_failure": True, + "application_logging.enabled": True, + "application_logging.forwarding.enabled": True, + "application_logging.metrics.enabled": True, + "application_logging.local_decorating.enabled": True, + "event_harvest_config.harvest_limits.log_event_data": 100000, +} + +collector_agent_registration = collector_agent_registration_fixture( + app_name="Python Agent Test (logger_loguru)", + default_settings=_default_settings, +) + + +class CaplogHandler(logging.StreamHandler): + """ + To prevent possible issues with pytest's monkey patching + use a custom Caplog handler to capture all records + """ + def __init__(self, *args, **kwargs): + self.records = [] + super(CaplogHandler, self).__init__(*args, **kwargs) + + def emit(self, record): + self.records.append(self.format(record)) + + +@pytest.fixture(scope="function") +def logger(): + import loguru + _logger = loguru.logger + caplog = CaplogHandler() + handler_id = _logger.add(caplog, level="WARNING", format="{message}") + _logger.caplog = caplog + yield _logger + del caplog.records[:] + _logger.remove(handler_id) diff --git a/tests/logger_loguru/test_local_decorating.py b/tests/logger_loguru/test_local_decorating.py new file mode 100644 index 0000000000..ad5d59599b --- /dev/null +++ b/tests/logger_loguru/test_local_decorating.py @@ -0,0 +1,88 @@ +# 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 platform + +from newrelic.api.application import application_settings +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.fixtures import ( + validate_transaction_metrics, +) + + +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.warning("C") + + +def get_metadata_string(log_message, is_txn): + host = platform.uname().node + assert host + entity_guid = application_settings().entity_guid + if is_txn: + metadata_string = "".join(('NR-LINKING|', entity_guid, '|', host, '|abcdefgh12345678|abcdefgh|Python%20Agent%20Test%20%28logger_loguru%29|')) + else: + metadata_string = "".join(('NR-LINKING|', entity_guid, '|', host, '|||Python%20Agent%20Test%20%28logger_loguru%29|')) + formatted_string = log_message + " " + metadata_string + return formatted_string + + +@reset_core_stats_engine() +def test_local_log_decoration_inside_transaction(logger): + @validate_log_event_count(1) + @background_task() + def test(): + exercise_logging(logger) + assert logger.caplog.records[0] == get_metadata_string('C', True) + + test() + + +@reset_core_stats_engine() +def test_local_log_decoration_outside_transaction(logger): + @validate_log_event_count_outside_transaction(1) + def test(): + exercise_logging(logger) + assert logger.caplog.records[0] == get_metadata_string('C', False) + + test() + + +@reset_core_stats_engine() +def test_patcher_application_order(logger): + def patch(record): + record["message"] += "-PATCH" + return record + + @validate_log_event_count_outside_transaction(1) + def test(): + patch_logger = logger.patch(patch) + exercise_logging(patch_logger) + assert logger.caplog.records[0] == get_metadata_string('C-PATCH', False) + + test() diff --git a/tests/logger_loguru/test_log_forwarding.py b/tests/logger_loguru/test_log_forwarding.py new file mode 100644 index 0000000000..34b9a2bb69 --- /dev/null +++ b/tests/logger_loguru/test_log_forwarding.py @@ -0,0 +1,94 @@ +# 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 logging + +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.debug("A") + # logger.info("B") + logger.warning("C") + logger.error("D") + logger.critical("E") + + assert len(logger.caplog.records) == 3 + + +_common_attributes_service_linking = {"timestamp": None, "hostname": None, "entity.name": "Python Agent Test (logger_loguru)", "entity.guid": None} +_common_attributes_trace_linking = {"span.id": "abcdefgh", "trace.id": "abcdefgh12345678", **_common_attributes_service_linking} + +_test_logging_inside_transaction_events = [ + {"message": "C", "level": "WARNING", **_common_attributes_trace_linking}, + {"message": "D", "level": "ERROR", **_common_attributes_trace_linking}, + {"message": "E", "level": "CRITICAL", **_common_attributes_trace_linking}, +] + + +@reset_core_stats_engine() +def test_logging_inside_transaction(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 = [ + {"message": "C", "level": "WARNING", **_common_attributes_service_linking}, + {"message": "D", "level": "ERROR", **_common_attributes_service_linking}, + {"message": "E", "level": "CRITICAL", **_common_attributes_service_linking}, +] + +@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) + def test(): + exercise_logging(logger) + + test() + + +@reset_core_stats_engine() +def test_logging_newrelic_logs_not_forwarded(logger): + @validate_log_event_count(0) + @background_task() + def test(): + nr_logger = logging.getLogger("newrelic") + nr_logger.addHandler(logger.caplog) + nr_logger.error("A") + assert len(logger.caplog.records) == 1 + + test() diff --git a/tests/logger_loguru/test_metrics.py b/tests/logger_loguru/test_metrics.py new file mode 100644 index 0000000000..9f57b33c1d --- /dev/null +++ b/tests/logger_loguru/test_metrics.py @@ -0,0 +1,61 @@ +# Copyright 2010 New Relic, Inc. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +from newrelic.api.background_task import background_task +from testing_support.fixtures import reset_core_stats_engine +from testing_support.validators.validate_custom_metrics_outside_transaction import validate_custom_metrics_outside_transaction +from testing_support.fixtures import ( + validate_transaction_metrics, +) + + +def exercise_logging(logger): + # logger.debug("A") + # logger.info("B") + logger.warning("C") + logger.error("D") + logger.critical("E") + + assert len(logger.caplog.records) == 3 + + +_test_logging_unscoped_metrics = [ + ("Logging/lines", 3), + ("Logging/lines/WARNING", 1), + ("Logging/lines/ERROR", 1), + ("Logging/lines/CRITICAL", 1), +] + +@reset_core_stats_engine() +def test_logging_metrics_inside_transaction(logger): + @validate_transaction_metrics( + "test_metrics:test_logging_metrics_inside_transaction..test", + custom_metrics=_test_logging_unscoped_metrics, + background_task=True, + ) + @background_task() + def test(): + exercise_logging(logger) + + test() + + +@reset_core_stats_engine() +def test_logging_metrics_outside_transaction(logger): + @validate_custom_metrics_outside_transaction(_test_logging_unscoped_metrics) + @reset_core_stats_engine() + def test(): + exercise_logging(logger) + + test() diff --git a/tests/logger_loguru/test_settings.py b/tests/logger_loguru/test_settings.py new file mode 100644 index 0000000000..4e5dadf5d3 --- /dev/null +++ b/tests/logger_loguru/test_settings.py @@ -0,0 +1,109 @@ +# 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 +import platform + +from newrelic.api.application import application_settings +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.fixtures import ( + override_application_settings, + validate_transaction_metrics, +) + + +def get_metadata_string(log_message, is_txn): + host = platform.uname().node + assert host + entity_guid = application_settings().entity_guid + if is_txn: + metadata_string = "".join(('NR-LINKING|', entity_guid, '|', host, '|abcdefgh12345678|abcdefgh|Python%20Agent%20Test%20%28internal_logging%29|')) + else: + metadata_string = "".join(('NR-LINKING|', entity_guid, '|', host, '|||Python%20Agent%20Test%20%28internal_logging%29|')) + formatted_string = log_message + " " + metadata_string + return formatted_string + + +def basic_logging(logger): + logger.warning("C") + + +_settings_matrix = [ + (True, True, True), + (True, False, False), + (False, True, False), + (False, False, False), +] + + +@pytest.mark.parametrize("feature_setting,subfeature_setting,expected", _settings_matrix) +@reset_core_stats_engine() +def test_log_forwarding_settings(logger, feature_setting, subfeature_setting, expected): + @override_application_settings({ + "application_logging.enabled": feature_setting, + "application_logging.forwarding.enabled": subfeature_setting, + }) + @validate_log_event_count(1 if expected else 0) + @background_task() + def test(): + basic_logging(logger) + assert len(logger.caplog.records) == 1 + + test() + + +@pytest.mark.parametrize("feature_setting,subfeature_setting,expected", _settings_matrix) +@reset_core_stats_engine() +def test_local_decorating_settings(logger, feature_setting, subfeature_setting, expected): + @override_application_settings({ + "application_logging.enabled": feature_setting, + "application_logging.local_decorating.enabled": subfeature_setting, + }) + @background_task() + def test(): + basic_logging(logger) + assert len(logger.caplog.records) == 1 + message = logger.caplog.records.pop() + if expected: + assert len(message) > 1 + else: + assert len(message) == 1 + + test() + + +@pytest.mark.parametrize("feature_setting,subfeature_setting,expected", _settings_matrix) +@reset_core_stats_engine() +def test_log_metrics_settings(logger, feature_setting, subfeature_setting, expected): + metric_count = 1 if expected else None + @override_application_settings({ + "application_logging.enabled": feature_setting, + "application_logging.metrics.enabled": subfeature_setting, + }) + @validate_transaction_metrics( + "test_settings:test_log_metrics_settings..test", + custom_metrics=[ + ("Logging/lines", metric_count), + ("Logging/lines/WARNING", metric_count), + ], + background_task=True, + ) + @background_task() + def test(): + basic_logging(logger) + assert len(logger.caplog.records) == 1 + + test() diff --git a/tox.ini b/tox.ini index 181ecac2af..02ae488d9f 100644 --- a/tox.ini +++ b/tox.ini @@ -140,6 +140,8 @@ envlist = python-framework_starlette-{py36,py37,py38,py39,py310,pypy3}-starlette{latest}, python-framework_strawberry-{py37,py38,py39,py310}-strawberrylatest, python-logger_logging-{py27,py36,py37,py38,py39,py310,pypy,pypy3}, + python-logger_loguru-{py36,py37,py38,py39,py310}-logurulatest, + python-logger_loguru-py39-loguru{06,05,04,03}, libcurl-framework_tornado-{py36,py37,py38,py39,py310,pypy3}-tornado0600, libcurl-framework_tornado-{py37,py38,py39,py310}-tornadomaster, rabbitmq-messagebroker_pika-{py27,py36,py37,py38,py39,pypy,pypy3}-pika0.13, @@ -325,7 +327,12 @@ deps = framework_tornado: pycurl framework_tornado-tornado0600: tornado<6.1 framework_tornado-tornadomaster: https://github.com/tornadoweb/tornado/archive/master.zip - framework-tornado: pycurl + framework_tornado: pycurl + logger_loguru-logurulatest: loguru + logger_loguru-loguru06: loguru<0.7 + logger_loguru-loguru05: loguru<0.6 + logger_loguru-loguru04: loguru<0.5 + logger_loguru-loguru03: loguru<0.4 messagebroker_pika-pika0.13: pika<0.14 messagebroker_pika-pikalatest: pika messagebroker_pika: tornado<5 @@ -423,5 +430,6 @@ changedir = framework_strawberry: tests/framework_strawberry framework_tornado: tests/framework_tornado logger_logging: tests/logger_logging + logger_loguru: tests/logger_loguru messagebroker_pika: tests/messagebroker_pika template_mako: tests/template_mako