Remove other framework changes

Author: TimPansino

newrelic/hooks/logger_logging.py

@@ -27,7 +27,7 @@
     from urllib.parse import quote
 
 
-IGNORED_LOG_RECORD_KEYS = set(["message", "msg"])
+DEFAULT_LOG_RECORD_KEYS = frozenset(set(vars(LogRecord("", 0, "", 0, "", (), None))) | {"message"})
 
 
 def add_nr_linking_metadata(message):
@@ -52,6 +52,15 @@ def bind_callHandlers(record):
     return record
 
 
+def filter_record_attributes(record):
+    record_attrs = vars(record)
+    custom_attr_keys = set(record_attrs.keys()) - DEFAULT_LOG_RECORD_KEYS
+    if custom_attr_keys:
+        return {k: record_attrs[k] for k in custom_attr_keys if k not in DEFAULT_LOG_RECORD_KEYS}
+    else:
+        return None
+
+
 def wrap_callHandlers(wrapped, instance, args, kwargs):
     transaction = current_transaction()
     record = bind_callHandlers(*args, **kwargs)
@@ -80,17 +89,10 @@ def wrap_callHandlers(wrapped, instance, args, kwargs):
 
         if settings.application_logging.forwarding and settings.application_logging.forwarding.enabled:
             try:
-                message = record.msg
-                if not isinstance(message, dict):
-                    # Allow python to convert the message to a string and template it with args.
-                    message = record.getMessage()
-
-                # Grab and filter context attributes from log record
-                record_attrs = vars(record)
-                context_attrs = {k: record_attrs[k] for k in vars(record) if k not in IGNORED_LOG_RECORD_KEYS}
-                
+                message = record.getMessage()
+                attrs = filter_record_attributes(record)
                 record_log_event(
-                    message=message, level=level_name, timestamp=int(record.created * 1000), attributes=context_attrs
+                    message=message, level=level_name, timestamp=int(record.created * 1000), attributes=attrs
                 )
             except Exception:
                 pass

newrelic/hooks/logger_structlog.py

@@ -12,17 +12,14 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
-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.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
+from newrelic.common.signature import bind_args
 
 
-@functools.cache
 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.
@@ -37,7 +34,14 @@ def bind_process_event(method_name, event, event_kw):
     return method_name, event, event_kw
 
 
-def new_relic_event_consumer(logger, level, event):
+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:
@@ -46,28 +50,16 @@ def new_relic_event_consumer(logger, level, event):
         settings = global_settings()
 
     # Return early if application logging not enabled
-    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:
-                # TODO CHECK ON THIS
-                event["event"] = message
+    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)
 
-        level_name = normalize_level_name(level)
+        # 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.enabled:
+        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})
@@ -77,34 +69,15 @@ def new_relic_event_consumer(logger, level, event):
                     application.record_custom_metric("Logging/lines", {"count": 1})
                     application.record_custom_metric("Logging/lines/%s" % level_name, {"count": 1})
 
-        if settings.application_logging.forwarding.enabled:
+        if settings.application_logging.forwarding and settings.application_logging.forwarding.enabled:
             try:
-                record_log_event(original_message, level_name, attributes=event_attrs)
+                record_log_event(original_message, level_name)
 
             except Exception:
                 pass
 
-    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 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 the result from wrapped after we've recorded the resulting log event.
+        return result
 
     return wrapped(*args, **kwargs)
 

tests/logger_logging/conftest.py

@@ -26,7 +26,6 @@
     "debug.record_transaction_failure": True,
     "application_logging.enabled": True,
     "application_logging.forwarding.enabled": True,
-    "application_logging.forwarding.context_data.enabled": True,
     "application_logging.metrics.enabled": True,
     "application_logging.local_decorating.enabled": True,
     "event_harvest_config.harvest_limits.log_event_data": 100000,

tests/logger_logging/test_attribute_forwarding.py

@@ -0,0 +1,65 @@
+# 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 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 newrelic.api.background_task import background_task
+
+_event_attributes = {"message": "A", "context.key": "value"}
+
+
+def exercise_logging(logger):
+    logger.error("A", extra={"key": "value"})
+    assert len(logger.caplog.records) == 1
+
+
+@override_application_settings(
+    {
+        "application_logging.forwarding.context_data.enabled": True,
+    }
+)
+def test_attributes_inside_transaction(logger):
+    @validate_log_events([_event_attributes])
+    @validate_log_event_count(1)
+    @background_task()
+    def test():
+        exercise_logging(logger)
+
+    test()
+
+
+@reset_core_stats_engine()
+@override_application_settings(
+    {
+        "application_logging.forwarding.context_data.enabled": True,
+    }
+)
+def test_attributes_outside_transaction(logger):
+    @validate_log_events_outside_transaction([_event_attributes])
+    @validate_log_event_count_outside_transaction(1)
+    def test():
+        exercise_logging(logger)
+
+    test()

tests/logger_logging/test_attributes.py

@@ -35,10 +35,10 @@ def set_trace_ids():
         trace.guid = "abcdefgh"
 
 
-def exercise_logging(logger, message="C"):
+def exercise_logging(logger):
     set_trace_ids()
 
-    logger.warning(message)
+    logger.warning("C")
 
 
 def get_metadata_string(log_message, is_txn):
@@ -82,14 +82,3 @@ def test():
         assert logger.caplog.records[0] == get_metadata_string("C", False)
 
     test()
-
-
-@reset_core_stats_engine()
-def test_local_log_decoration_dict_message(logger):
-    @validate_log_event_count(1)
-    @background_task()
-    def test():
-        exercise_logging(logger, {"message": "dict_message"})
-        assert logger.caplog.records[0] == get_metadata_string("{'message': 'dict_message'}", True)
-
-    test()