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 <tpansino@newrelic.com>
Co-authored-by: Lalleh Rafeei <lrafeei@newrelic.com>

* Remove pylint codes from flake8 config (#701)

* Create pytest fixtures and cleanup tests.

Co-authored-by: Tim Pansino <tpansino@newrelic.com>
Co-authored-by: Lalleh Rafeei <lrafeei@newrelic.com>
Co-authored-by: Timothy Pansino <11214426+TimPansino@users.noreply.github.com>
Co-authored-by: Hannah Stepanek <hstepanek@newrelic.com>

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

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)

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 "<StructLogCapLog %s>" % 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

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

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