From 2267d7dd71076321c207e6d84aa1f6a81e81f713 Mon Sep 17 00:00:00 2001 From: Uma Annamalai Date: Fri, 2 Dec 2022 10:52:22 -0800 Subject: [PATCH] Add structlog instrumentation. (#685) * Add initial structlog instrumentation. * Cleanup. * Add processor filtering and attribute testing. * Add more filtering tests. * Add co-authors. Co-authored-by: Tim Pansino Co-authored-by: Lalleh Rafeei * Remove pylint codes from flake8 config (#701) * Create pytest fixtures and cleanup tests. Co-authored-by: Tim Pansino Co-authored-by: Lalleh Rafeei Co-authored-by: Timothy Pansino <11214426+TimPansino@users.noreply.github.com> Co-authored-by: Hannah Stepanek --- newrelic/config.py | 5 + newrelic/hooks/logger_structlog.py | 86 ++++++++++ tests/logger_structlog/conftest.py | 150 ++++++++++++++++++ .../test_attribute_forwarding.py | 49 ++++++ .../logger_structlog/test_local_decorating.py | 54 +++++++ tests/logger_structlog/test_log_forwarding.py | 88 ++++++++++ tests/logger_structlog/test_metrics.py | 73 +++++++++ tox.ini | 3 + 8 files changed, 508 insertions(+) create mode 100644 newrelic/hooks/logger_structlog.py create mode 100644 tests/logger_structlog/conftest.py create mode 100644 tests/logger_structlog/test_attribute_forwarding.py create mode 100644 tests/logger_structlog/test_local_decorating.py create mode 100644 tests/logger_structlog/test_log_forwarding.py create mode 100644 tests/logger_structlog/test_metrics.py diff --git a/newrelic/config.py b/newrelic/config.py index a57af4505..9bf890bc3 100644 --- a/newrelic/config.py +++ b/newrelic/config.py @@ -2360,6 +2360,11 @@ def _process_module_builtin_defaults(): "newrelic.hooks.logger_loguru", "instrument_loguru_logger", ) + _process_module_definition( + "structlog._base", + "newrelic.hooks.logger_structlog", + "instrument_structlog__base", + ) _process_module_definition( "paste.httpserver", diff --git a/newrelic/hooks/logger_structlog.py b/newrelic/hooks/logger_structlog.py new file mode 100644 index 000000000..8b34b285f --- /dev/null +++ b/newrelic/hooks/logger_structlog.py @@ -0,0 +1,86 @@ +# 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.common.object_wrapper import wrap_function_wrapper +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 + + +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. + try: + from structlog._log_levels import _LEVEL_TO_NAME, _NAME_TO_LEVEL + return _LEVEL_TO_NAME[_NAME_TO_LEVEL[method_name]].upper() + except Exception: + return "UNKNOWN" + + +def bind_process_event(method_name, event, event_kw): + return method_name, event, event_kw + + +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: + 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: + if settings.application_logging.local_decorating and settings.application_logging.local_decorating.enabled: + event = add_nr_linking_metadata(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) + + level_name = normalize_level_name(method_name) + + 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(original_message, level_name, attributes=event_kw) + + except Exception: + pass + + # Return the result from wrapped after we've recorded the resulting log event. + return result + + return wrapped(*args, **kwargs) + + +def instrument_structlog__base(module): + if hasattr(module, "BoundLoggerBase") and hasattr(module.BoundLoggerBase, "_process_event"): + wrap_function_wrapper(module, "BoundLoggerBase._process_event", wrap__process_event) diff --git a/tests/logger_structlog/conftest.py b/tests/logger_structlog/conftest.py new file mode 100644 index 000000000..7f896d043 --- /dev/null +++ b/tests/logger_structlog/conftest.py @@ -0,0 +1,150 @@ +# 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 structlog import DropEvent, PrintLogger +from newrelic.api.time_trace import current_trace +from newrelic.api.transaction import current_transaction +from testing_support.fixtures import ( + code_coverage_fixture, + collector_agent_registration_fixture, + collector_available_fixture, +) + +_coverage_source = [ + "newrelic.hooks.logger_structlog", +] + +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_structlog)", + default_settings=_default_settings, +) + + +class StructLogCapLog(PrintLogger): + def __init__(self, caplog): + self.caplog = caplog if caplog is not None else [] + + def msg(self, event, **kwargs): + self.caplog.append(event) + return + + log = debug = info = warn = warning = msg + fatal = failure = err = error = critical = exception = msg + + def __repr__(self): + return "" % str(id(self)) + + __str__ = __repr__ + + +@pytest.fixture +def set_trace_ids(): + def _set(): + txn = current_transaction() + if txn: + txn._trace_id = "abcdefgh12345678" + trace = current_trace() + if trace: + trace.guid = "abcdefgh" + return _set + +def drop_event_processor(logger, method_name, event_dict): + if method_name == "info": + raise DropEvent + else: + return event_dict + + +@pytest.fixture(scope="function") +def structlog_caplog(): + return list() + + +@pytest.fixture(scope="function") +def logger(structlog_caplog): + import structlog + structlog.configure(processors=[], logger_factory=lambda *args, **kwargs: StructLogCapLog(structlog_caplog)) + _logger = structlog.get_logger() + return _logger + + +@pytest.fixture(scope="function") +def filtering_logger(structlog_caplog): + import structlog + structlog.configure(processors=[drop_event_processor], logger_factory=lambda *args, **kwargs: StructLogCapLog(structlog_caplog)) + _filtering_logger = structlog.get_logger() + return _filtering_logger + + +@pytest.fixture +def exercise_logging_multiple_lines(set_trace_ids, logger, structlog_caplog): + def _exercise(): + set_trace_ids() + + logger.msg("Cat", a=42) + logger.error("Dog") + logger.critical("Elephant") + + assert len(structlog_caplog) == 3 + + assert "Cat" in structlog_caplog[0] + assert "Dog" in structlog_caplog[1] + assert "Elephant" in structlog_caplog[2] + + return _exercise + + +@pytest.fixture +def exercise_filtering_logging_multiple_lines(set_trace_ids, filtering_logger, structlog_caplog): + def _exercise(): + set_trace_ids() + + filtering_logger.msg("Cat", a=42) + filtering_logger.error("Dog") + filtering_logger.critical("Elephant") + + assert len(structlog_caplog) == 2 + + assert "Cat" not in structlog_caplog[0] + assert "Dog" in structlog_caplog[0] + assert "Elephant" in structlog_caplog[1] + + return _exercise + + +@pytest.fixture +def exercise_logging_single_line(set_trace_ids, logger, structlog_caplog): + def _exercise(): + set_trace_ids() + logger.error("A", key="value") + assert len(structlog_caplog) == 1 + + return _exercise diff --git a/tests/logger_structlog/test_attribute_forwarding.py b/tests/logger_structlog/test_attribute_forwarding.py new file mode 100644 index 000000000..2d514b01a --- /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", "context.key": "value"} + + +@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_local_decorating.py b/tests/logger_structlog/test_local_decorating.py new file mode 100644 index 000000000..7b58d4a0c --- /dev/null +++ b/tests/logger_structlog/test_local_decorating.py @@ -0,0 +1,54 @@ +# Copyright 2010 New Relic, Inc. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +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.validators.validate_log_event_count_outside_transaction import validate_log_event_count_outside_transaction + + +def get_metadata_string(log_message, is_txn): + host = platform.uname()[1] + 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_structlog%29|')) + else: + metadata_string = "".join(('NR-LINKING|', entity_guid, '|', host, '|||Python%20Agent%20Test%20%28logger_structlog%29|')) + formatted_string = log_message + " " + metadata_string + return formatted_string + + +@reset_core_stats_engine() +def test_local_log_decoration_inside_transaction(exercise_logging_single_line, structlog_caplog): + @validate_log_event_count(1) + @background_task() + def test(): + exercise_logging_single_line() + assert get_metadata_string('A', True) in structlog_caplog[0] + + test() + + +@reset_core_stats_engine() +def test_local_log_decoration_outside_transaction(exercise_logging_single_line, structlog_caplog): + @validate_log_event_count_outside_transaction(1) + def test(): + exercise_logging_single_line() + assert get_metadata_string('A', False) in structlog_caplog[0] + + test() diff --git a/tests/logger_structlog/test_log_forwarding.py b/tests/logger_structlog/test_log_forwarding.py new file mode 100644 index 000000000..e5a5e670f --- /dev/null +++ b/tests/logger_structlog/test_log_forwarding.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. + +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 + + +_common_attributes_service_linking = {"timestamp": None, "hostname": None, + "entity.name": "Python Agent Test (logger_structlog)", "entity.guid": None} + +_common_attributes_trace_linking = {"span.id": "abcdefgh", "trace.id": "abcdefgh12345678", + **_common_attributes_service_linking} + + +@reset_core_stats_engine() +@override_application_settings({"application_logging.local_decorating.enabled": False}) +def test_logging_inside_transaction(exercise_logging_multiple_lines): + @validate_log_events([ + {"message": "Cat", "level": "INFO", **_common_attributes_trace_linking}, + {"message": "Dog", "level": "ERROR", **_common_attributes_trace_linking}, + {"message": "Elephant", "level": "CRITICAL", **_common_attributes_trace_linking}, + ]) + @validate_log_event_count(3) + @background_task() + def test(): + exercise_logging_multiple_lines() + + test() + + +@reset_core_stats_engine() +@override_application_settings({"application_logging.local_decorating.enabled": False}) +def test_logging_filtering_inside_transaction(exercise_filtering_logging_multiple_lines): + @validate_log_events([ + {"message": "Dog", "level": "ERROR", **_common_attributes_trace_linking}, + {"message": "Elephant", "level": "CRITICAL", **_common_attributes_trace_linking}, + ]) + @validate_log_event_count(2) + @background_task() + def test(): + exercise_filtering_logging_multiple_lines() + + test() + + +@reset_core_stats_engine() +@override_application_settings({"application_logging.local_decorating.enabled": False}) +def test_logging_outside_transaction(exercise_logging_multiple_lines): + @validate_log_events_outside_transaction([ + {"message": "Cat", "level": "INFO", **_common_attributes_service_linking}, + {"message": "Dog", "level": "ERROR", **_common_attributes_service_linking}, + {"message": "Elephant", "level": "CRITICAL", **_common_attributes_service_linking}, + ]) + @validate_log_event_count_outside_transaction(3) + def test(): + exercise_logging_multiple_lines() + + test() + + +@reset_core_stats_engine() +@override_application_settings({"application_logging.local_decorating.enabled": False}) +def test_logging_filtering_outside_transaction(exercise_filtering_logging_multiple_lines): + @validate_log_events_outside_transaction([ + {"message": "Dog", "level": "ERROR", **_common_attributes_service_linking}, + {"message": "Elephant", "level": "CRITICAL", **_common_attributes_service_linking}, + ]) + @validate_log_event_count_outside_transaction(2) + def test(): + exercise_filtering_logging_multiple_lines() + + test() diff --git a/tests/logger_structlog/test_metrics.py b/tests/logger_structlog/test_metrics.py new file mode 100644 index 000000000..48f7204e8 --- /dev/null +++ b/tests/logger_structlog/test_metrics.py @@ -0,0 +1,73 @@ +# 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.packages import six +from newrelic.api.background_task import background_task +from testing_support.fixtures import reset_core_stats_engine +from testing_support.validators.validate_transaction_metrics import validate_transaction_metrics +from testing_support.validators.validate_custom_metrics_outside_transaction import validate_custom_metrics_outside_transaction + + +_test_logging_unscoped_metrics = [ + ("Logging/lines", 3), + ("Logging/lines/INFO", 1), + ("Logging/lines/ERROR", 1), + ("Logging/lines/CRITICAL", 1), +] + + +@reset_core_stats_engine() +def test_logging_metrics_inside_transaction(exercise_logging_multiple_lines): + txn_name = "test_metrics:test_logging_metrics_inside_transaction..test" if six.PY3 else "test_metrics:test" + @validate_transaction_metrics( + txn_name, + custom_metrics=_test_logging_unscoped_metrics, + background_task=True, + ) + @background_task() + def test(): + exercise_logging_multiple_lines() + + test() + + +@reset_core_stats_engine() +def test_logging_metrics_outside_transaction(exercise_logging_multiple_lines): + @validate_custom_metrics_outside_transaction(_test_logging_unscoped_metrics) + def test(): + exercise_logging_multiple_lines() + + test() + + +_test_logging_unscoped_filtering_metrics = [ + ("Logging/lines", 2), + ("Logging/lines/ERROR", 1), + ("Logging/lines/CRITICAL", 1), +] + + +@reset_core_stats_engine() +def test_filtering_logging_metrics_inside_transaction(exercise_filtering_logging_multiple_lines): + txn_name = "test_metrics:test_filtering_logging_metrics_inside_transaction..test" if six.PY3 else "test_metrics:test" + @validate_transaction_metrics( + txn_name, + custom_metrics=_test_logging_unscoped_filtering_metrics, + background_task=True, + ) + @background_task() + def test(): + exercise_filtering_logging_multiple_lines() + + test() diff --git a/tox.ini b/tox.ini index c815defc2..20fc77cae 100644 --- a/tox.ini +++ b/tox.ini @@ -151,6 +151,7 @@ envlist = python-framework_strawberry-{py37,py38,py39,py310,py311}-strawberrylatest, python-logger_logging-{py27,py37,py38,py39,py310,py311,pypy,pypy37}, python-logger_loguru-{py37,py38,py39,py310,py311,pypy37}-logurulatest, + python-logger_structlog-{py37,py38,py39,py310,py311,pypy37}-structloglatest, python-logger_loguru-py39-loguru{06,05,04,03}, libcurl-framework_tornado-{py37,py38,py39,py310,py311,pypy37}-tornado0600, libcurl-framework_tornado-{py38,py39,py310,py311}-tornadomaster, @@ -368,6 +369,7 @@ deps = logger_loguru-loguru05: loguru<0.6 logger_loguru-loguru04: loguru<0.5 logger_loguru-loguru03: loguru<0.4 + logger_structlog-structloglatest: structlog messagebroker_pika-pika0.13: pika<0.14 messagebroker_pika-pikalatest: pika messagebroker_pika: tornado<5 @@ -484,6 +486,7 @@ changedir = framework_tornado: tests/framework_tornado logger_logging: tests/logger_logging logger_loguru: tests/logger_loguru + logger_structlog: tests/logger_structlog messagebroker_pika: tests/messagebroker_pika messagebroker_confluentkafka: tests/messagebroker_confluentkafka messagebroker_kafkapython: tests/messagebroker_kafkapython