From 11709577f0d5135632b626d087b68ac38fc361ea Mon Sep 17 00:00:00 2001 From: Uma Annamalai Date: Mon, 7 Nov 2022 10:44:43 -0800 Subject: [PATCH 1/7] Add initial structlog instrumentation. --- newrelic/config.py | 16 ++- newrelic/hooks/logger_structlog.py | 72 +++++++++++++ tests/logger_structlog/conftest.py | 54 ++++++++++ .../logger_structlog/test_local_decorating.py | 72 +++++++++++++ tests/logger_structlog/test_log_forwarding.py | 100 ++++++++++++++++++ tests/logger_structlog/test_metrics.py | 59 +++++++++++ tox.ini | 3 + 7 files changed, 375 insertions(+), 1 deletion(-) create mode 100644 newrelic/hooks/logger_structlog.py create mode 100644 tests/logger_structlog/conftest.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..b6ebea64e 100644 --- a/newrelic/config.py +++ b/newrelic/config.py @@ -2360,7 +2360,21 @@ def _process_module_builtin_defaults(): "newrelic.hooks.logger_loguru", "instrument_loguru_logger", ) - + _process_module_definition( + "loguru._logger", + "newrelic.hooks.logger_loguru", + "instrument_loguru_logger", + ) + _process_module_definition( + "structlog._log_levels", + "newrelic.hooks.logger_structlog", + "instrument_structlog__log_levels", + ) + _process_module_definition( + "structlog._config", + "newrelic.hooks.logger_structlog", + "instrument_structlog__config", + ) _process_module_definition( "paste.httpserver", "newrelic.hooks.adapter_paste", diff --git a/newrelic/hooks/logger_structlog.py b/newrelic/hooks/logger_structlog.py new file mode 100644 index 000000000..8038bffd2 --- /dev/null +++ b/newrelic/hooks/logger_structlog.py @@ -0,0 +1,72 @@ +# 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 calendar +import time + +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 bind_add_log_level(logger, method_name, event_dict): + return logger, method_name, event_dict + +def wrap_add_log_level(wrapped, instance, args, kwargs): + logger, method_name, event_dict = bind_add_log_level(*args, **kwargs) + if method_name == "warn": + method_name = "warning" + + method_name = method_name.upper() + + 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: + level_name = "UNKNOWN" if not method_name else (method_name or "UNKNOWN") + message = event_dict["event"] + + 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: + #TODO: get timestamp + record_log_event(message, level_name, calendar.timegm(time.gmtime())) + except Exception: + pass + + if settings.application_logging.local_decorating and settings.application_logging.local_decorating.enabled: + event_dict["_nr_original_message"] = message + event_dict["event"] = add_nr_linking_metadata(message) + + return wrapped(*args, **kwargs) + + +def instrument_structlog__log_levels(module): + if hasattr(module, "add_log_level"): + wrap_function_wrapper(module, "add_log_level", wrap_add_log_level) diff --git a/tests/logger_structlog/conftest.py b/tests/logger_structlog/conftest.py new file mode 100644 index 000000000..aae364e6e --- /dev/null +++ b/tests/logger_structlog/conftest.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 logging +import pytest + +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, +) + + +@pytest.fixture(scope="function") +def logger(): + import structlog + _logger = structlog.get_logger() + yield _logger + diff --git a/tests/logger_structlog/test_local_decorating.py b/tests/logger_structlog/test_local_decorating.py new file mode 100644 index 000000000..8a39c73c6 --- /dev/null +++ b/tests/logger_structlog/test_local_decorating.py @@ -0,0 +1,72 @@ +# 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 + + +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, capsys): + set_trace_ids() + + logger.warning("C") + + +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(logger, capsys): + @validate_log_event_count(1) + @background_task() + def test(): + exercise_logging(logger, capsys) + output = capsys.readouterr()[0] + assert get_metadata_string('C', True) in output + + test() + + +@reset_core_stats_engine() +def test_local_log_decoration_outside_transaction(logger, capsys): + @validate_log_event_count_outside_transaction(1) + def test(): + exercise_logging(logger, capsys) + output = capsys.readouterr()[0] + assert get_metadata_string('C', False) in output + + 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..23aaef826 --- /dev/null +++ b/tests/logger_structlog/test_log_forwarding.py @@ -0,0 +1,100 @@ +# 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 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, capsys): + set_trace_ids() + + logger.msg("Cat", a=42) + logger.error("Dog") + logger.critical("Elephant") + output = capsys.readouterr() + assert "Cat" in output[0] + assert "Dog" in output[0] + assert "Elephant" in output[0] + + +_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} + +_test_logging_inside_transaction_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}, +] + + +@reset_core_stats_engine() +def test_logging_inside_transaction(logger, capsys): + @validate_log_events(_test_logging_inside_transaction_events) + @validate_log_event_count(3) + @background_task() + def test(): + exercise_logging(logger, capsys) + + test() + + +_test_logging_outside_transaction_events = [ + {"message": "Cat", "level": "INFO", **_common_attributes_service_linking}, + {"message": "Dog", "level": "ERROR", **_common_attributes_service_linking}, + {"message": "Elephant", "level": "CRITICAL", **_common_attributes_service_linking}, +] + + +@reset_core_stats_engine() +def test_logging_outside_transaction(logger, capsys): + @validate_log_events_outside_transaction(_test_logging_outside_transaction_events) + @validate_log_event_count_outside_transaction(3) + def test(): + exercise_logging(logger, capsys) + + test() + + +@reset_core_stats_engine() +def test_logging_newrelic_logs_not_forwarded(logger, capsys): + @validate_log_event_count(0) + @background_task() + def test(): + nr_logger = logging.getLogger("newrelic") + nr_logger.warning("A") + output = capsys.readouterr()[1] + assert "warning" not in output + + test() diff --git a/tests/logger_structlog/test_metrics.py b/tests/logger_structlog/test_metrics.py new file mode 100644 index 000000000..39a51fddc --- /dev/null +++ b/tests/logger_structlog/test_metrics.py @@ -0,0 +1,59 @@ +# 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_custom_metrics_outside_transaction import validate_custom_metrics_outside_transaction +from testing_support.fixtures import ( + validate_transaction_metrics, +) + + +def exercise_logging(logger, capsys): + logger.msg("Cat", a=42) + logger.error("Dog") + logger.critical("Elephant") + + + +_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(logger, capsys): + 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(logger, capsys) + + test() + + +@reset_core_stats_engine() +def test_logging_metrics_outside_transaction(logger, capsys): + @validate_custom_metrics_outside_transaction(_test_logging_unscoped_metrics) + def test(): + exercise_logging(logger, capsys) + + test() diff --git a/tox.ini b/tox.ini index f8e2b2e0c..b34e28925 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-{py37,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 From e9efd877d9558acca4a4ad9600b6d9ec7350a836 Mon Sep 17 00:00:00 2001 From: Uma Annamalai Date: Mon, 7 Nov 2022 11:47:37 -0800 Subject: [PATCH 2/7] Cleanup. --- newrelic/config.py | 10 ---------- newrelic/hooks/logger_structlog.py | 4 ++-- 2 files changed, 2 insertions(+), 12 deletions(-) diff --git a/newrelic/config.py b/newrelic/config.py index b6ebea64e..26d01303d 100644 --- a/newrelic/config.py +++ b/newrelic/config.py @@ -2360,21 +2360,11 @@ def _process_module_builtin_defaults(): "newrelic.hooks.logger_loguru", "instrument_loguru_logger", ) - _process_module_definition( - "loguru._logger", - "newrelic.hooks.logger_loguru", - "instrument_loguru_logger", - ) _process_module_definition( "structlog._log_levels", "newrelic.hooks.logger_structlog", "instrument_structlog__log_levels", ) - _process_module_definition( - "structlog._config", - "newrelic.hooks.logger_structlog", - "instrument_structlog__config", - ) _process_module_definition( "paste.httpserver", "newrelic.hooks.adapter_paste", diff --git a/newrelic/hooks/logger_structlog.py b/newrelic/hooks/logger_structlog.py index 8038bffd2..41279e6d5 100644 --- a/newrelic/hooks/logger_structlog.py +++ b/newrelic/hooks/logger_structlog.py @@ -24,6 +24,7 @@ def bind_add_log_level(logger, method_name, event_dict): return logger, method_name, event_dict + def wrap_add_log_level(wrapped, instance, args, kwargs): logger, method_name, event_dict = bind_add_log_level(*args, **kwargs) if method_name == "warn": @@ -41,7 +42,7 @@ def wrap_add_log_level(wrapped, instance, args, kwargs): # Return early if application logging not enabled if settings and settings.application_logging and settings.application_logging.enabled: level_name = "UNKNOWN" if not method_name else (method_name or "UNKNOWN") - message = event_dict["event"] + message = event_dict["event"] #Structlog records are stored in an event dictionary where the log message key is "event" if settings.application_logging.metrics and settings.application_logging.metrics.enabled: if transaction: @@ -55,7 +56,6 @@ def wrap_add_log_level(wrapped, instance, args, kwargs): if settings.application_logging.forwarding and settings.application_logging.forwarding.enabled: try: - #TODO: get timestamp record_log_event(message, level_name, calendar.timegm(time.gmtime())) except Exception: pass From bb2747a63afa86f25d56300b485066cf51396286 Mon Sep 17 00:00:00 2001 From: Uma Annamalai Date: Mon, 14 Nov 2022 16:37:07 -0800 Subject: [PATCH 3/7] Add processor filtering and attribute testing. --- newrelic/config.py | 5 +- newrelic/hooks/logger_structlog.py | 51 +++++++++++------- tests/logger_structlog/conftest.py | 37 ++++++++++++- .../test_attribute_forwarding.py | 54 +++++++++++++++++++ .../logger_structlog/test_local_decorating.py | 16 +++--- tests/logger_structlog/test_log_forwarding.py | 36 +++++-------- tests/logger_structlog/test_metrics.py | 42 +++++++++++++-- 7 files changed, 184 insertions(+), 57 deletions(-) create mode 100644 tests/logger_structlog/test_attribute_forwarding.py diff --git a/newrelic/config.py b/newrelic/config.py index 26d01303d..9bf890bc3 100644 --- a/newrelic/config.py +++ b/newrelic/config.py @@ -2361,10 +2361,11 @@ def _process_module_builtin_defaults(): "instrument_loguru_logger", ) _process_module_definition( - "structlog._log_levels", + "structlog._base", "newrelic.hooks.logger_structlog", - "instrument_structlog__log_levels", + "instrument_structlog__base", ) + _process_module_definition( "paste.httpserver", "newrelic.hooks.adapter_paste", diff --git a/newrelic/hooks/logger_structlog.py b/newrelic/hooks/logger_structlog.py index 41279e6d5..6ad2dea6a 100644 --- a/newrelic/hooks/logger_structlog.py +++ b/newrelic/hooks/logger_structlog.py @@ -11,8 +11,6 @@ # 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 calendar -import time from newrelic.common.object_wrapper import wrap_function_wrapper from newrelic.api.transaction import current_transaction, record_log_event @@ -21,16 +19,27 @@ from newrelic.hooks.logger_logging import add_nr_linking_metadata -def bind_add_log_level(logger, method_name, event_dict): - return logger, method_name, event_dict +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 wrap_add_log_level(wrapped, instance, args, kwargs): - logger, method_name, event_dict = bind_add_log_level(*args, **kwargs) - if method_name == "warn": - method_name = "warning" +def bind_process_event(method_name, event, event_kw): + return method_name, event, event_kw - method_name = method_name.upper() + +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() @@ -41,8 +50,13 @@ def wrap_add_log_level(wrapped, instance, args, kwargs): # Return early if application logging not enabled if settings and settings.application_logging and settings.application_logging.enabled: - level_name = "UNKNOWN" if not method_name else (method_name or "UNKNOWN") - message = event_dict["event"] #Structlog records are stored in an event dictionary where the log message key is "event" + 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: @@ -56,17 +70,18 @@ def wrap_add_log_level(wrapped, instance, args, kwargs): if settings.application_logging.forwarding and settings.application_logging.forwarding.enabled: try: - record_log_event(message, level_name, calendar.timegm(time.gmtime())) + #record_log_event(original_message, level_name, attributes=event_kw) + record_log_event(original_message, level_name) + except Exception: pass - if settings.application_logging.local_decorating and settings.application_logging.local_decorating.enabled: - event_dict["_nr_original_message"] = message - event_dict["event"] = add_nr_linking_metadata(message) + # Return the result from wrapped after we've recorded the resulting log event. + return result return wrapped(*args, **kwargs) -def instrument_structlog__log_levels(module): - if hasattr(module, "add_log_level"): - wrap_function_wrapper(module, "add_log_level", wrap_add_log_level) +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 index aae364e6e..fee12d3f1 100644 --- a/tests/logger_structlog/conftest.py +++ b/tests/logger_structlog/conftest.py @@ -14,6 +14,7 @@ import logging import pytest +from structlog import DropEvent, PrintLogger from testing_support.fixtures import ( code_coverage_fixture, @@ -46,9 +47,43 @@ ) +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__ + +def drop_event_processor(logger, method_name, event_dict): + if method_name == "info": + raise DropEvent + else: + return event_dict + @pytest.fixture(scope="function") -def logger(): +def structlog_caplog(): + yield 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() yield _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() + yield _filtering_logger diff --git a/tests/logger_structlog/test_attribute_forwarding.py b/tests/logger_structlog/test_attribute_forwarding.py new file mode 100644 index 000000000..fec54cfc5 --- /dev/null +++ b/tests/logger_structlog/test_attribute_forwarding.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. + +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 +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 testing_support.fixtures import override_application_settings + + +_event_attributes = {"message": "A", "context.key": "value", "context.int_attr": "1", "context.dict_attr": '{"key":"value"}'} + + +def exercise_logging(logger, structlog_caplog): + logger.error("A", key="value") + assert len(structlog_caplog) == 1 + +@override_application_settings({ + "application_logging.forwarding.context_data.enabled": True, +}) +def test_attributes_inside_transaction(logger, structlog_caplog): + @validate_log_events([_event_attributes]) + @validate_log_event_count(1) + @background_task() + def test(): + exercise_logging(logger, structlog_caplog) + + test() + + +@reset_core_stats_engine() +@override_application_settings({ + "application_logging.forwarding.context_data.enabled": True, +}) +def test_attributes_outside_transaction(logger, structlog_caplog): + @validate_log_events_outside_transaction([_event_attributes]) + @validate_log_event_count_outside_transaction(1) + def test(): + exercise_logging(logger, structlog_caplog) + + test() \ No newline at end of file diff --git a/tests/logger_structlog/test_local_decorating.py b/tests/logger_structlog/test_local_decorating.py index 8a39c73c6..18b7721fb 100644 --- a/tests/logger_structlog/test_local_decorating.py +++ b/tests/logger_structlog/test_local_decorating.py @@ -31,7 +31,7 @@ def set_trace_ids(): if trace: trace.guid = "abcdefgh" -def exercise_logging(logger, capsys): +def exercise_logging(logger, structlog_caplog): set_trace_ids() logger.warning("C") @@ -50,23 +50,21 @@ def get_metadata_string(log_message, is_txn): @reset_core_stats_engine() -def test_local_log_decoration_inside_transaction(logger, capsys): +def test_local_log_decoration_inside_transaction(logger, structlog_caplog): @validate_log_event_count(1) @background_task() def test(): - exercise_logging(logger, capsys) - output = capsys.readouterr()[0] - assert get_metadata_string('C', True) in output + exercise_logging(logger, structlog_caplog) + assert get_metadata_string('C', True) in structlog_caplog[0] test() @reset_core_stats_engine() -def test_local_log_decoration_outside_transaction(logger, capsys): +def test_local_log_decoration_outside_transaction(logger, structlog_caplog): @validate_log_event_count_outside_transaction(1) def test(): - exercise_logging(logger, capsys) - output = capsys.readouterr()[0] - assert get_metadata_string('C', False) in output + exercise_logging(logger, structlog_caplog) + assert get_metadata_string('C', False) in structlog_caplog[0] test() diff --git a/tests/logger_structlog/test_log_forwarding.py b/tests/logger_structlog/test_log_forwarding.py index 23aaef826..1bf67f605 100644 --- a/tests/logger_structlog/test_log_forwarding.py +++ b/tests/logger_structlog/test_log_forwarding.py @@ -18,7 +18,7 @@ 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.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 @@ -35,16 +35,18 @@ def set_trace_ids(): trace.guid = "abcdefgh" -def exercise_logging(logger, capsys): +def exercise_logging(logger, structlog_caplog): set_trace_ids() logger.msg("Cat", a=42) logger.error("Dog") logger.critical("Elephant") - output = capsys.readouterr() - assert "Cat" in output[0] - assert "Dog" in output[0] - assert "Elephant" in output[0] + + assert len(structlog_caplog) == 3 + + assert "Cat" in structlog_caplog[0] + assert "Dog" in structlog_caplog[1] + assert "Elephant" in structlog_caplog[2] _common_attributes_service_linking = {"timestamp": None, "hostname": None, @@ -60,12 +62,13 @@ def exercise_logging(logger, capsys): @reset_core_stats_engine() -def test_logging_inside_transaction(logger, capsys): +@override_application_settings({"application_logging.local_decorating.enabled": False}) +def test_logging_inside_transaction(logger, structlog_caplog): @validate_log_events(_test_logging_inside_transaction_events) @validate_log_event_count(3) @background_task() def test(): - exercise_logging(logger, capsys) + exercise_logging(logger, structlog_caplog) test() @@ -78,23 +81,12 @@ def test(): @reset_core_stats_engine() -def test_logging_outside_transaction(logger, capsys): +@override_application_settings({"application_logging.local_decorating.enabled": False}) +def test_logging_outside_transaction(logger, structlog_caplog): @validate_log_events_outside_transaction(_test_logging_outside_transaction_events) @validate_log_event_count_outside_transaction(3) def test(): - exercise_logging(logger, capsys) + exercise_logging(logger, structlog_caplog) test() - -@reset_core_stats_engine() -def test_logging_newrelic_logs_not_forwarded(logger, capsys): - @validate_log_event_count(0) - @background_task() - def test(): - nr_logger = logging.getLogger("newrelic") - nr_logger.warning("A") - output = capsys.readouterr()[1] - assert "warning" not in output - - test() diff --git a/tests/logger_structlog/test_metrics.py b/tests/logger_structlog/test_metrics.py index 39a51fddc..7ff33e41c 100644 --- a/tests/logger_structlog/test_metrics.py +++ b/tests/logger_structlog/test_metrics.py @@ -21,11 +21,22 @@ ) -def exercise_logging(logger, capsys): +def exercise_logging(logger, structlog_caplog): 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] + + +def exercise_filtering_logging(filtering_logger, structlog_caplog): + filtering_logger.msg("Cat", a=42) + filtering_logger.error("Dog") + filtering_logger.critical("Elephant") _test_logging_unscoped_metrics = [ @@ -36,7 +47,7 @@ def exercise_logging(logger, capsys): ] @reset_core_stats_engine() -def test_logging_metrics_inside_transaction(logger, capsys): +def test_logging_metrics_inside_transaction(logger, structlog_caplog): txn_name = "test_metrics:test_logging_metrics_inside_transaction..test" if six.PY3 else "test_metrics:test" @validate_transaction_metrics( txn_name, @@ -45,15 +56,36 @@ def test_logging_metrics_inside_transaction(logger, capsys): ) @background_task() def test(): - exercise_logging(logger, capsys) + exercise_logging(logger, structlog_caplog) + + 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(filtering_logger, structlog_caplog): + 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(filtering_logger, structlog_caplog) test() + @reset_core_stats_engine() -def test_logging_metrics_outside_transaction(logger, capsys): +def test_logging_metrics_outside_transaction(logger, structlog_caplog): @validate_custom_metrics_outside_transaction(_test_logging_unscoped_metrics) def test(): - exercise_logging(logger, capsys) + exercise_logging(logger, structlog_caplog) test() From 5cee7b0e7aab151d00ec591b7460d27a11dbc176 Mon Sep 17 00:00:00 2001 From: Uma Annamalai Date: Thu, 17 Nov 2022 13:02:04 -0800 Subject: [PATCH 4/7] Add more filtering tests. --- newrelic/hooks/logger_structlog.py | 3 +- tests/logger_structlog/conftest.py | 1 + .../test_attribute_forwarding.py | 7 ++- .../logger_structlog/test_local_decorating.py | 6 +-- tests/logger_structlog/test_log_forwarding.py | 47 +++++++++++++++++++ tests/logger_structlog/test_metrics.py | 12 +++-- 6 files changed, 63 insertions(+), 13 deletions(-) diff --git a/newrelic/hooks/logger_structlog.py b/newrelic/hooks/logger_structlog.py index 6ad2dea6a..8b34b285f 100644 --- a/newrelic/hooks/logger_structlog.py +++ b/newrelic/hooks/logger_structlog.py @@ -70,8 +70,7 @@ def wrap__process_event(wrapped, instance, args, kwargs): if settings.application_logging.forwarding and settings.application_logging.forwarding.enabled: try: - #record_log_event(original_message, level_name, attributes=event_kw) - record_log_event(original_message, level_name) + record_log_event(original_message, level_name, attributes=event_kw) except Exception: pass diff --git a/tests/logger_structlog/conftest.py b/tests/logger_structlog/conftest.py index fee12d3f1..014889704 100644 --- a/tests/logger_structlog/conftest.py +++ b/tests/logger_structlog/conftest.py @@ -81,6 +81,7 @@ def logger(structlog_caplog): _logger = structlog.get_logger() yield _logger + @pytest.fixture(scope="function") def filtering_logger(structlog_caplog): import structlog diff --git a/tests/logger_structlog/test_attribute_forwarding.py b/tests/logger_structlog/test_attribute_forwarding.py index fec54cfc5..39baac66d 100644 --- a/tests/logger_structlog/test_attribute_forwarding.py +++ b/tests/logger_structlog/test_attribute_forwarding.py @@ -13,15 +13,14 @@ # limitations under the License. from newrelic.api.background_task import background_task -from testing_support.fixtures import reset_core_stats_engine +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 testing_support.fixtures import override_application_settings -_event_attributes = {"message": "A", "context.key": "value", "context.int_attr": "1", "context.dict_attr": '{"key":"value"}'} +_event_attributes = {"message": "A", "context.key": "value"} def exercise_logging(logger, structlog_caplog): @@ -51,4 +50,4 @@ def test_attributes_outside_transaction(logger, structlog_caplog): def test(): exercise_logging(logger, structlog_caplog) - test() \ No newline at end of file + test() diff --git a/tests/logger_structlog/test_local_decorating.py b/tests/logger_structlog/test_local_decorating.py index 18b7721fb..2a457ec6a 100644 --- a/tests/logger_structlog/test_local_decorating.py +++ b/tests/logger_structlog/test_local_decorating.py @@ -31,7 +31,7 @@ def set_trace_ids(): if trace: trace.guid = "abcdefgh" -def exercise_logging(logger, structlog_caplog): +def exercise_logging(logger): set_trace_ids() logger.warning("C") @@ -54,7 +54,7 @@ def test_local_log_decoration_inside_transaction(logger, structlog_caplog): @validate_log_event_count(1) @background_task() def test(): - exercise_logging(logger, structlog_caplog) + exercise_logging(logger) assert get_metadata_string('C', True) in structlog_caplog[0] test() @@ -64,7 +64,7 @@ def test(): def test_local_log_decoration_outside_transaction(logger, structlog_caplog): @validate_log_event_count_outside_transaction(1) def test(): - exercise_logging(logger, structlog_caplog) + exercise_logging(logger) assert get_metadata_string('C', False) in structlog_caplog[0] test() diff --git a/tests/logger_structlog/test_log_forwarding.py b/tests/logger_structlog/test_log_forwarding.py index 1bf67f605..a15740211 100644 --- a/tests/logger_structlog/test_log_forwarding.py +++ b/tests/logger_structlog/test_log_forwarding.py @@ -49,6 +49,19 @@ def exercise_logging(logger, structlog_caplog): assert "Elephant" in structlog_caplog[2] +def exercise_filtering_logging(filtering_logger, structlog_caplog): + 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] + _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", @@ -73,6 +86,24 @@ def test(): test() +_test_logging_filtering_inside_transaction_events = [ + {"message": "Dog", "level": "ERROR", **_common_attributes_trace_linking}, + {"message": "Elephant", "level": "CRITICAL", **_common_attributes_trace_linking}, +] + + +@reset_core_stats_engine() +@override_application_settings({"application_logging.local_decorating.enabled": False}) +def test_logging_filtering_inside_transaction(filtering_logger, structlog_caplog): + @validate_log_events(_test_logging_filtering_inside_transaction_events) + @validate_log_event_count(2) + @background_task() + def test(): + exercise_filtering_logging(filtering_logger, structlog_caplog) + + test() + + _test_logging_outside_transaction_events = [ {"message": "Cat", "level": "INFO", **_common_attributes_service_linking}, {"message": "Dog", "level": "ERROR", **_common_attributes_service_linking}, @@ -90,3 +121,19 @@ def test(): test() + +_test_logging_filtering_outside_transaction_events = [ + {"message": "Dog", "level": "ERROR", **_common_attributes_service_linking}, + {"message": "Elephant", "level": "CRITICAL", **_common_attributes_service_linking}, +] + + +@reset_core_stats_engine() +@override_application_settings({"application_logging.local_decorating.enabled": False}) +def test_logging_filtering_outside_transaction(filtering_logger, structlog_caplog): + @validate_log_events_outside_transaction(_test_logging_filtering_outside_transaction_events) + @validate_log_event_count_outside_transaction(2) + def test(): + exercise_filtering_logging(filtering_logger, structlog_caplog) + + test() diff --git a/tests/logger_structlog/test_metrics.py b/tests/logger_structlog/test_metrics.py index 7ff33e41c..e1ded3867 100644 --- a/tests/logger_structlog/test_metrics.py +++ b/tests/logger_structlog/test_metrics.py @@ -15,10 +15,9 @@ 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 -from testing_support.fixtures import ( - validate_transaction_metrics, -) + def exercise_logging(logger, structlog_caplog): @@ -38,6 +37,12 @@ def exercise_filtering_logging(filtering_logger, structlog_caplog): 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] + _test_logging_unscoped_metrics = [ ("Logging/lines", 3), @@ -81,7 +86,6 @@ def test(): test() - @reset_core_stats_engine() def test_logging_metrics_outside_transaction(logger, structlog_caplog): @validate_custom_metrics_outside_transaction(_test_logging_unscoped_metrics) From 7cc73d9d11c6905b37e4de6b476a5b6544eb03b6 Mon Sep 17 00:00:00 2001 From: Uma Annamalai Date: Thu, 17 Nov 2022 13:34:17 -0800 Subject: [PATCH 5/7] Add co-authors. Co-authored-by: Tim Pansino Co-authored-by: Lalleh Rafeei From 67feaa7cb788440017d342e91a6d270736267530 Mon Sep 17 00:00:00 2001 From: Hannah Stepanek Date: Mon, 28 Nov 2022 12:13:43 -0800 Subject: [PATCH 6/7] Remove pylint codes from flake8 config (#701) --- setup.cfg | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/setup.cfg b/setup.cfg index 544bdbea3..453a10eeb 100644 --- a/setup.cfg +++ b/setup.cfg @@ -5,4 +5,4 @@ license_files = [flake8] max-line-length = 120 -extend-ignore = C0103,C0115,C0116,C0415,E0401,E1120,E122,E126,E127,E128,E203,E501,E722,F841,R1725,W0613,W0613,W504 +extend-ignore = E122,E126,E127,E128,E203,E501,E722,F841,W504 From 934b8d5695ded60f9663b0c953cda0e932bb4214 Mon Sep 17 00:00:00 2001 From: Uma Annamalai Date: Wed, 30 Nov 2022 13:48:33 -0800 Subject: [PATCH 7/7] Create pytest fixtures and cleanup tests. --- tests/logger_structlog/conftest.py | 68 +++++++++++- .../test_attribute_forwarding.py | 12 +- .../logger_structlog/test_local_decorating.py | 28 +---- tests/logger_structlog/test_log_forwarding.py | 105 +++++------------- tests/logger_structlog/test_metrics.py | 54 +++------ 5 files changed, 117 insertions(+), 150 deletions(-) diff --git a/tests/logger_structlog/conftest.py b/tests/logger_structlog/conftest.py index 014889704..7f896d043 100644 --- a/tests/logger_structlog/conftest.py +++ b/tests/logger_structlog/conftest.py @@ -15,7 +15,8 @@ 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, @@ -63,15 +64,28 @@ def __repr__(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(): - yield list() + return list() @pytest.fixture(scope="function") @@ -79,7 +93,7 @@ def logger(structlog_caplog): import structlog structlog.configure(processors=[], logger_factory=lambda *args, **kwargs: StructLogCapLog(structlog_caplog)) _logger = structlog.get_logger() - yield _logger + return _logger @pytest.fixture(scope="function") @@ -87,4 +101,50 @@ 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() - yield _filtering_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 index 39baac66d..2d514b01a 100644 --- a/tests/logger_structlog/test_attribute_forwarding.py +++ b/tests/logger_structlog/test_attribute_forwarding.py @@ -23,19 +23,15 @@ _event_attributes = {"message": "A", "context.key": "value"} -def exercise_logging(logger, structlog_caplog): - logger.error("A", key="value") - assert len(structlog_caplog) == 1 - @override_application_settings({ "application_logging.forwarding.context_data.enabled": True, }) -def test_attributes_inside_transaction(logger, structlog_caplog): +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(logger, structlog_caplog) + exercise_logging_single_line() test() @@ -44,10 +40,10 @@ def test(): @override_application_settings({ "application_logging.forwarding.context_data.enabled": True, }) -def test_attributes_outside_transaction(logger, structlog_caplog): +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(logger, structlog_caplog) + exercise_logging_single_line() test() diff --git a/tests/logger_structlog/test_local_decorating.py b/tests/logger_structlog/test_local_decorating.py index 2a457ec6a..7b58d4a0c 100644 --- a/tests/logger_structlog/test_local_decorating.py +++ b/tests/logger_structlog/test_local_decorating.py @@ -16,27 +16,11 @@ 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 -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()[1] assert host @@ -50,21 +34,21 @@ def get_metadata_string(log_message, is_txn): @reset_core_stats_engine() -def test_local_log_decoration_inside_transaction(logger, structlog_caplog): +def test_local_log_decoration_inside_transaction(exercise_logging_single_line, structlog_caplog): @validate_log_event_count(1) @background_task() def test(): - exercise_logging(logger) - assert get_metadata_string('C', True) in structlog_caplog[0] + 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(logger, structlog_caplog): +def test_local_log_decoration_outside_transaction(exercise_logging_single_line, structlog_caplog): @validate_log_event_count_outside_transaction(1) def test(): - exercise_logging(logger) - assert get_metadata_string('C', False) in structlog_caplog[0] + 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 index a15740211..e5a5e670f 100644 --- a/tests/logger_structlog/test_log_forwarding.py +++ b/tests/logger_structlog/test_log_forwarding.py @@ -12,12 +12,7 @@ # See the License for the specific language governing permissions and # limitations under the License. -import logging -import pytest - 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 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 \ @@ -26,114 +21,68 @@ 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, structlog_caplog): - 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] - - -def exercise_filtering_logging(filtering_logger, structlog_caplog): - 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] - _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} -_test_logging_inside_transaction_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}, -] - @reset_core_stats_engine() @override_application_settings({"application_logging.local_decorating.enabled": False}) -def test_logging_inside_transaction(logger, structlog_caplog): - @validate_log_events(_test_logging_inside_transaction_events) +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(logger, structlog_caplog) + exercise_logging_multiple_lines() test() -_test_logging_filtering_inside_transaction_events = [ - {"message": "Dog", "level": "ERROR", **_common_attributes_trace_linking}, - {"message": "Elephant", "level": "CRITICAL", **_common_attributes_trace_linking}, -] - - @reset_core_stats_engine() @override_application_settings({"application_logging.local_decorating.enabled": False}) -def test_logging_filtering_inside_transaction(filtering_logger, structlog_caplog): - @validate_log_events(_test_logging_filtering_inside_transaction_events) +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(filtering_logger, structlog_caplog) + exercise_filtering_logging_multiple_lines() test() -_test_logging_outside_transaction_events = [ - {"message": "Cat", "level": "INFO", **_common_attributes_service_linking}, - {"message": "Dog", "level": "ERROR", **_common_attributes_service_linking}, - {"message": "Elephant", "level": "CRITICAL", **_common_attributes_service_linking}, -] - - @reset_core_stats_engine() @override_application_settings({"application_logging.local_decorating.enabled": False}) -def test_logging_outside_transaction(logger, structlog_caplog): - @validate_log_events_outside_transaction(_test_logging_outside_transaction_events) +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(logger, structlog_caplog) + exercise_logging_multiple_lines() test() -_test_logging_filtering_outside_transaction_events = [ - {"message": "Dog", "level": "ERROR", **_common_attributes_service_linking}, - {"message": "Elephant", "level": "CRITICAL", **_common_attributes_service_linking}, -] - - @reset_core_stats_engine() @override_application_settings({"application_logging.local_decorating.enabled": False}) -def test_logging_filtering_outside_transaction(filtering_logger, structlog_caplog): - @validate_log_events_outside_transaction(_test_logging_filtering_outside_transaction_events) +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(filtering_logger, structlog_caplog) + exercise_filtering_logging_multiple_lines() test() diff --git a/tests/logger_structlog/test_metrics.py b/tests/logger_structlog/test_metrics.py index e1ded3867..48f7204e8 100644 --- a/tests/logger_structlog/test_metrics.py +++ b/tests/logger_structlog/test_metrics.py @@ -19,31 +19,6 @@ from testing_support.validators.validate_custom_metrics_outside_transaction import validate_custom_metrics_outside_transaction - -def exercise_logging(logger, structlog_caplog): - 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] - - -def exercise_filtering_logging(filtering_logger, structlog_caplog): - 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] - - _test_logging_unscoped_metrics = [ ("Logging/lines", 3), ("Logging/lines/INFO", 1), @@ -51,8 +26,9 @@ def exercise_filtering_logging(filtering_logger, structlog_caplog): ("Logging/lines/CRITICAL", 1), ] + @reset_core_stats_engine() -def test_logging_metrics_inside_transaction(logger, structlog_caplog): +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, @@ -61,18 +37,29 @@ def test_logging_metrics_inside_transaction(logger, structlog_caplog): ) @background_task() def test(): - exercise_logging(logger, structlog_caplog) + 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(filtering_logger, structlog_caplog): +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, @@ -81,15 +68,6 @@ def test_filtering_logging_metrics_inside_transaction(filtering_logger, structlo ) @background_task() def test(): - exercise_filtering_logging(filtering_logger, structlog_caplog) - - test() - - -@reset_core_stats_engine() -def test_logging_metrics_outside_transaction(logger, structlog_caplog): - @validate_custom_metrics_outside_transaction(_test_logging_unscoped_metrics) - def test(): - exercise_logging(logger, structlog_caplog) + exercise_filtering_logging_multiple_lines() test()