diff --git a/newrelic/common/signature.py b/newrelic/common/signature.py index 3149981962..3fe516bdc2 100644 --- a/newrelic/common/signature.py +++ b/newrelic/common/signature.py @@ -18,7 +18,7 @@ from inspect import Signature def bind_args(func, args, kwargs): - """Bind arguments and apply defaults to missing arugments for a callable.""" + """Bind arguments and apply defaults to missing arguments for a callable.""" bound_args = Signature.from_callable(func).bind(*args, **kwargs) bound_args.apply_defaults() return bound_args.arguments @@ -27,5 +27,5 @@ def bind_args(func, args, kwargs): from inspect import getcallargs def bind_args(func, args, kwargs): - """Bind arguments and apply defaults to missing arugments for a callable.""" + """Bind arguments and apply defaults to missing arguments for a callable.""" return getcallargs(func, *args, **kwargs) diff --git a/newrelic/config.py b/newrelic/config.py index 997fe1a776..d08d51dff7 100644 --- a/newrelic/config.py +++ b/newrelic/config.py @@ -2471,7 +2471,11 @@ def _process_module_builtin_defaults(): "newrelic.hooks.logger_structlog", "instrument_structlog__base", ) - + _process_module_definition( + "structlog._frames", + "newrelic.hooks.logger_structlog", + "instrument_structlog__frames", + ) _process_module_definition( "paste.httpserver", "newrelic.hooks.adapter_paste", diff --git a/newrelic/hooks/logger_structlog.py b/newrelic/hooks/logger_structlog.py index e652a795c8..06d13aa4aa 100644 --- a/newrelic/hooks/logger_structlog.py +++ b/newrelic/hooks/logger_structlog.py @@ -17,6 +17,7 @@ from newrelic.core.config import global_settings from newrelic.api.application import application_instance from newrelic.hooks.logger_logging import add_nr_linking_metadata +from newrelic.common.signature import bind_args def normalize_level_name(method_name): @@ -81,6 +82,25 @@ def wrap__process_event(wrapped, instance, args, kwargs): return wrapped(*args, **kwargs) +def wrap__find_first_app_frame_and_name(wrapped, instance, args, kwargs): + try: + bound_args = bind_args(wrapped, args, kwargs) + if bound_args["additional_ignores"]: + bound_args["additional_ignores"] = list(bound_args["additional_ignores"]) + bound_args["additional_ignores"].append("newrelic") + else: + bound_args["additional_ignores"] = ["newrelic"] + except Exception: + return wrapped(*args, **kwargs) + + return wrapped(**bound_args) + + 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) + + +def instrument_structlog__frames(module): + if hasattr(module, "_find_first_app_frame_and_name"): + wrap_function_wrapper(module, "_find_first_app_frame_and_name", wrap__find_first_app_frame_and_name) diff --git a/tests/logger_structlog/conftest.py b/tests/logger_structlog/conftest.py index 05a86d8a7c..191d687c9c 100644 --- a/tests/logger_structlog/conftest.py +++ b/tests/logger_structlog/conftest.py @@ -14,7 +14,6 @@ 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 ( @@ -41,21 +40,27 @@ ) -class StructLogCapLog(PrintLogger): - def __init__(self, caplog): - self.caplog = caplog if caplog is not None else [] +@pytest.fixture(scope="session") +def StructLogCapLog(): + from structlog import PrintLogger - def msg(self, event, **kwargs): - self.caplog.append(event) - return + class _StructLogCapLog(PrintLogger): + def __init__(self, caplog=None): + self.caplog = caplog if caplog is not None else [] - log = debug = info = warn = warning = msg - fatal = failure = err = error = critical = exception = msg + def msg(self, event, **kwargs): + self.caplog.append(event) + return - def __repr__(self): - return "" % str(id(self)) + log = debug = info = warn = warning = msg + fatal = failure = err = error = critical = exception = msg - __str__ = __repr__ + def __repr__(self): + return "" % str(id(self)) + + __str__ = __repr__ + + return _StructLogCapLog @pytest.fixture @@ -67,9 +72,13 @@ def _set(): trace = current_trace() if trace: trace.guid = "abcdefgh" + return _set + def drop_event_processor(logger, method_name, event_dict): + from structlog import DropEvent + if method_name == "info": raise DropEvent else: @@ -77,14 +86,15 @@ def drop_event_processor(logger, method_name, event_dict): @pytest.fixture(scope="function") -def structlog_caplog(): - return list() +def structlog_caplog(StructLogCapLog): + return StructLogCapLog() @pytest.fixture(scope="function") def logger(structlog_caplog): import structlog - structlog.configure(processors=[], logger_factory=lambda *args, **kwargs: StructLogCapLog(structlog_caplog)) + + structlog.configure(processors=[], logger_factory=lambda *args, **kwargs: structlog_caplog) _logger = structlog.get_logger() return _logger @@ -92,11 +102,36 @@ def logger(structlog_caplog): @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)) + + structlog.configure( + processors=[drop_event_processor], logger_factory=lambda *args, **kwargs: structlog_caplog + ) _filtering_logger = structlog.get_logger() return _filtering_logger +@pytest.fixture(scope="function") +def callsite_parameter_logger(structlog_caplog): + import structlog + + structlog.configure( + processors=[ + structlog.processors.CallsiteParameterAdder( + [ + structlog.processors.CallsiteParameter.FILENAME, + structlog.processors.CallsiteParameter.FUNC_NAME, + structlog.processors.CallsiteParameter.LINENO, + ], + ), + structlog.processors.KeyValueRenderer(), + ], + logger_factory=lambda *args, **kwargs: structlog_caplog, + ) + + _callsite_logger = structlog.get_logger() + return _callsite_logger + + @pytest.fixture def exercise_logging_multiple_lines(set_trace_ids, logger, structlog_caplog): def _exercise(): @@ -106,11 +141,11 @@ def _exercise(): logger.error("Dog") logger.critical("Elephant") - assert len(structlog_caplog) == 3 + assert len(structlog_caplog.caplog) == 3 - assert "Cat" in structlog_caplog[0] - assert "Dog" in structlog_caplog[1] - assert "Elephant" in structlog_caplog[2] + assert "Cat" in structlog_caplog.caplog[0] + assert "Dog" in structlog_caplog.caplog[1] + assert "Elephant" in structlog_caplog.caplog[2] return _exercise @@ -124,11 +159,11 @@ def _exercise(): filtering_logger.error("Dog") filtering_logger.critical("Elephant") - assert len(structlog_caplog) == 2 + assert len(structlog_caplog.caplog) == 2 - assert "Cat" not in structlog_caplog[0] - assert "Dog" in structlog_caplog[0] - assert "Elephant" in structlog_caplog[1] + assert "Cat" not in structlog_caplog.caplog[0] + assert "Dog" in structlog_caplog.caplog[0] + assert "Elephant" in structlog_caplog.caplog[1] return _exercise @@ -138,6 +173,6 @@ 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 + assert len(structlog_caplog.caplog) == 1 return _exercise diff --git a/tests/logger_structlog/test_local_decorating.py b/tests/logger_structlog/test_local_decorating.py index 7b58d4a0cd..78e99d2385 100644 --- a/tests/logger_structlog/test_local_decorating.py +++ b/tests/logger_structlog/test_local_decorating.py @@ -39,7 +39,7 @@ def test_local_log_decoration_inside_transaction(exercise_logging_single_line, s @background_task() def test(): exercise_logging_single_line() - assert get_metadata_string('A', True) in structlog_caplog[0] + assert get_metadata_string('A', True) in structlog_caplog.caplog[0] test() @@ -49,6 +49,6 @@ def test_local_log_decoration_outside_transaction(exercise_logging_single_line, @validate_log_event_count_outside_transaction(1) def test(): exercise_logging_single_line() - assert get_metadata_string('A', False) in structlog_caplog[0] + assert get_metadata_string('A', False) in structlog_caplog.caplog[0] test() diff --git a/tests/logger_structlog/test_structlog_processors.py b/tests/logger_structlog/test_structlog_processors.py new file mode 100644 index 0000000000..cf6887c583 --- /dev/null +++ b/tests/logger_structlog/test_structlog_processors.py @@ -0,0 +1,25 @@ +# 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 + + +@reset_core_stats_engine() +@background_task() +def test_callsite_parameter_processor(callsite_parameter_logger, structlog_caplog): + callsite_parameter_logger.msg("Dog") + assert "Dog" in structlog_caplog.caplog[0] + assert "filename='test_structlog_processors.py'" in structlog_caplog.caplog[0] + assert "func_name='test_callsite_parameter_processor'" in structlog_caplog.caplog[0]