Fix bug with Structlog CallsiteParameter processor

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)

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",

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)

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 "<StructLogCapLog %s>" % str(id(self))
+        log = debug = info = warn = warning = msg
+        fatal = failure = err = error = critical = exception = msg
 
-    __str__ = __repr__
+        def __repr__(self):
+            return "<StructLogCapLog %s>" % str(id(self))
+
+        __str__ = __repr__
+
+    return _StructLogCapLog
 
 
 @pytest.fixture
@@ -67,36 +72,66 @@ 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:
         return 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
 
 
 @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

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()

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]