StructLog Attribute Instrumentation

newrelic/hooks/logger_structlog.py

@@ -12,19 +12,23 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
-from newrelic.common.object_wrapper import wrap_function_wrapper
+import functools
+
+from newrelic.api.application import application_instance
 from newrelic.api.transaction import current_transaction, record_log_event
+from newrelic.common.object_wrapper import wrap_function_wrapper
+from newrelic.common.signature import bind_args
 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
 
 
+@functools.lru_cache(maxsize=None)
 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"
@@ -34,14 +38,7 @@ 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
-
+def new_relic_event_consumer(logger, level, event):
     transaction = current_transaction()
 
     if transaction:
@@ -50,16 +47,27 @@ def wrap__process_event(wrapped, instance, args, kwargs):
         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)
+    if settings and settings.application_logging.enabled:
+        if isinstance(event, (str, bytes, bytearray)):
+            message = original_message = event
+            event_attrs = {}
+        elif isinstance(event, dict):
+            message = original_message = event.get("event", "")
+            event_attrs = {k: v for k, v in event.items() if k != "event"}
+        else:
+            # Unclear how to proceed, ignore log. Avoid logging an error message or we may incur an infinite loop.
+            return event
+
+        if settings.application_logging.local_decorating.enabled:
+            message = add_nr_linking_metadata(message)
+            if isinstance(event, (str, bytes, bytearray)):
+                event = message
+            elif isinstance(event, dict) and "event" in event:
+                event["event"] = message
 
-        # 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)
+        level_name = normalize_level_name(level)
 
-        if settings.application_logging.metrics and settings.application_logging.metrics.enabled:
+        if 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})
@@ -69,15 +77,34 @@ def wrap__process_event(wrapped, instance, args, kwargs):
                     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:
+        if settings.application_logging.forwarding.enabled:
             try:
-                record_log_event(original_message, level_name)
+                record_log_event(original_message, level_name, attributes=event_attrs)
 
             except Exception:
                 pass
 
-        # Return the result from wrapped after we've recorded the resulting log event.
-        return result
+    return event
+
+
+def wrap__process_event(wrapped, instance, args, kwargs):
+    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.enabled:
+        processors = instance._processors
+        if not processors:
+            instance._processors = [new_relic_event_consumer]
+        elif processors[-1] != new_relic_event_consumer:
+            # Remove our processor if it exists and add it to the end
+            if new_relic_event_consumer in processors:
+                processors.remove(new_relic_event_consumer)
+            processors.append(new_relic_event_consumer)
 
     return wrapped(*args, **kwargs)
 

tests/logger_structlog/conftest.py

@@ -12,15 +12,15 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
-import logging
 import pytest
-from newrelic.api.time_trace import current_trace
-from newrelic.api.transaction import current_transaction
-from testing_support.fixtures import (
+from testing_support.fixtures import (  # noqa: F401; pylint: disable=W0611
     collector_agent_registration_fixture,
     collector_available_fixture,
 )
 
+from newrelic.api.time_trace import current_trace
+from newrelic.api.transaction import current_transaction
+
 _default_settings = {
     "transaction_tracer.explain_threshold": 0.0,
     "transaction_tracer.transaction_threshold": 0.0,
@@ -31,6 +31,7 @@
     "application_logging.forwarding.enabled": True,
     "application_logging.metrics.enabled": True,
     "application_logging.local_decorating.enabled": True,
+    "application_logging.forwarding.context_data.enabled": True,
     "event_harvest_config.harvest_limits.log_event_data": 100000,
 }
 
@@ -103,9 +104,7 @@ def logger(structlog_caplog):
 def filtering_logger(structlog_caplog):
     import structlog
 
-    structlog.configure(
-        processors=[drop_event_processor], logger_factory=lambda *args, **kwargs: structlog_caplog
-    )
+    structlog.configure(processors=[drop_event_processor], logger_factory=lambda *args, **kwargs: structlog_caplog)
     _filtering_logger = structlog.get_logger()
     return _filtering_logger
 

tests/logger_structlog/test_attributes.py

@@ -0,0 +1,97 @@
+# 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 pytest
+from testing_support.validators.validate_log_event_count import validate_log_event_count
+from testing_support.validators.validate_log_events import validate_log_events
+
+from newrelic.api.background_task import background_task
+
+
+@pytest.fixture(scope="function")
+def logger(structlog_caplog):
+    import structlog
+
+    structlog.configure(
+        processors=[
+            structlog.contextvars.merge_contextvars,
+            structlog.processors.format_exc_info,
+            structlog.processors.StackInfoRenderer(),
+            structlog.processors.CallsiteParameterAdder(),
+        ],
+        logger_factory=lambda *args, **kwargs: structlog_caplog,
+    )
+
+    _callsite_logger = structlog.get_logger(logger_attr=2)
+    structlog.contextvars.bind_contextvars(context_attr=3)
+    yield _callsite_logger
+    structlog.contextvars.clear_contextvars()
+
+
+@validate_log_events(
+    [
+        {  # Fixed attributes
+            "message": "context_attrs: arg1",
+            "context.kwarg_attr": 1,
+            "context.logger_attr": 2,
+            "context.context_attr": 3,
+            "context.filename": "test_attributes.py",
+            "context.func_name": "test_structlog_default_context_attributes",
+            "context.module": "test_attributes",
+            "context.pathname": str(__file__),
+            "context.process_name": "MainProcess",
+            "context.thread_name": "MainThread",
+        }
+    ],
+    required_attrs=[  # Variable attributes
+        "context.lineno",
+        "context.process",
+        "context.thread",
+    ],
+)
+@validate_log_event_count(1)
+@background_task()
+def test_structlog_default_context_attributes(logger):
+    logger.error("context_attrs: %s", "arg1", kwarg_attr=1)
+
+
+@validate_log_events([{"message": "exc_info"}], required_attrs=["context.exception"])
+@validate_log_event_count(1)
+@background_task()
+def test_structlog_exc_info_context_attributes(logger):
+    try:
+        raise RuntimeError("Oops")
+    except Exception:
+        logger.error("exc_info", exc_info=True)
+
+
+@validate_log_events([{"message": "stack_info"}], required_attrs=["context.stack"])
+@validate_log_event_count(1)
+@background_task()
+def test_structlog_stack_info_context_attributes(logger):
+    logger.error("stack_info", stack_info=True)
+
+
+@validate_log_events([{"message": "A", "message.attr": 1}])
+@validate_log_event_count(1)
+@background_task()
+def test_structlog_message_attributes(logger):
+    logger.error({"message": "A", "attr": 1})
+
+
+@validate_log_events([{"message.attr": 1}])
+@validate_log_event_count(1)
+@background_task()
+def test_structlog_attributes_only(logger):
+    logger.error({"attr": 1})