Merge branch 'develop-logging-attributes' into feature-structlog-attrs

newrelic/common/encoding_utils.py

@@ -80,7 +80,7 @@ def json_encode(obj, **kwargs):
     # The third is eliminate white space after separators to trim the
     # size of the data being sent.
 
-    if type(b"") is type(""):  # NOQA
+    if type(b"") is type(""):  # noqa, pylint: disable=C0123
         _kwargs["encoding"] = "latin-1"
 
     def _encode(o):
@@ -267,7 +267,7 @@ def generate_path_hash(name, seed):
     if not isinstance(name, bytes):
         name = name.encode("UTF-8")
 
-    path_hash = rotated ^ int(hashlib.md5(name).hexdigest()[-8:], base=16)
+    path_hash = rotated ^ int(hashlib.md5(name).hexdigest()[-8:], base=16)  # nosec
     return "%08x" % path_hash
 
 

newrelic/hooks/logger_logging.py

@@ -12,22 +12,19 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
-from logging import Formatter, LogRecord
-
 from newrelic.api.application import application_instance
 from newrelic.api.time_trace import get_linking_metadata
 from newrelic.api.transaction import current_transaction, record_log_event
 from newrelic.common.object_wrapper import function_wrapper, wrap_function_wrapper
 from newrelic.core.config import global_settings
-from newrelic.packages import six
 
 try:
     from urllib import quote
 except ImportError:
     from urllib.parse import quote
 
 
-DEFAULT_LOG_RECORD_KEYS = frozenset(set(vars(LogRecord("", 0, "", 0, "", (), None))) | {"message"})
+IGNORED_LOG_RECORD_KEYS = set(["message", "msg"])
 
 
 def add_nr_linking_metadata(message):
@@ -52,15 +49,6 @@ 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)
@@ -89,10 +77,17 @@ def wrap_callHandlers(wrapped, instance, args, kwargs):
 
         if settings.application_logging.forwarding and settings.application_logging.forwarding.enabled:
             try:
-                message = record.getMessage()
-                attrs = filter_record_attributes(record)
+                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 record_attrs if k not in IGNORED_LOG_RECORD_KEYS}
+
                 record_log_event(
-                    message=message, level=level_name, timestamp=int(record.created * 1000), attributes=attrs
+                    message=message, level=level_name, timestamp=int(record.created * 1000), attributes=context_attrs
                 )
             except Exception:
                 pass

setup.cfg

@@ -5,4 +5,4 @@ license_files =
 
 [flake8]
 max-line-length = 120
-extend-ignore = E122,E126,E127,E128,E203,E501,E722,F841,W504,E731
+extend-ignore = E122,E126,E127,E128,E203,E501,E722,F841,W504,E731,F811

tests/logger_logging/conftest.py

@@ -13,10 +13,12 @@
 # limitations under the License.
 
 import logging
-import pytest
-
-from testing_support.fixtures import collector_agent_registration_fixture, collector_available_fixture  # noqa: F401; pylint: disable=W0611
 
+import pytest
+from testing_support.fixtures import (  # noqa: F401; pylint: disable=W0611
+    collector_agent_registration_fixture,
+    collector_available_fixture,
+)
 
 _default_settings = {
     "transaction_tracer.explain_threshold": 0.0,
@@ -26,6 +28,7 @@
     "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,
@@ -42,6 +45,7 @@ class CaplogHandler(logging.StreamHandler):
     To prevent possible issues with pytest's monkey patching
     use a custom Caplog handler to capture all records
     """
+
     def __init__(self, *args, **kwargs):
         self.records = []
         super(CaplogHandler, self).__init__(*args, **kwargs)

tests/logger_logging/test_attributes.py

@@ -0,0 +1,90 @@
+# 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
+from newrelic.packages import six
+
+
+@validate_log_events(
+    [
+        {  # Fixed attributes
+            "message": "context_attrs: arg1",
+            "context.args": "('arg1',)",
+            "context.filename": "test_attributes.py",
+            "context.funcName": "test_logging_default_context_attributes",
+            "context.levelname": "ERROR",
+            "context.levelno": 40,
+            "context.module": "test_attributes",
+            "context.name": "my_app",
+            "context.pathname": str(__file__),
+            "context.processName": "MainProcess",
+            "context.threadName": "MainThread",
+        }
+    ],
+    required_attrs=[  # Variable attributes
+        "context.created",
+        "context.lineno",
+        "context.msecs",
+        "context.process",
+        "context.relativeCreated",
+        "context.thread",
+    ],
+)
+@validate_log_event_count(1)
+@background_task()
+def test_logging_default_context_attributes(logger):
+    logger.error("context_attrs: %s", "arg1")
+
+
+@validate_log_events([{"message": "extras", "context.extra_attr": 1}])
+@validate_log_event_count(1)
+@background_task()
+def test_logging_extra_attributes(logger):
+    logger.error("extras", extra={"extra_attr": 1})
+
+
+@validate_log_events([{"message": "exc_info"}], required_attrs=["context.exc_info", "context.exc_text"])
+@validate_log_event_count(1)
+@background_task()
+def test_logging_exc_info_context_attributes(logger):
+    try:
+        raise RuntimeError("Oops")
+    except Exception:
+        logger.error("exc_info", exc_info=True)
+
+
+@pytest.mark.skipif(six.PY2, reason="stack_info on log messages not available in Python 2.")
+@validate_log_events([{"message": "stack_info"}], required_attrs=["context.stack_info"])
+@validate_log_event_count(1)
+@background_task()
+def test_logging_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_logging_dict_message_and_attributes(logger):
+    logger.error({"message": "A", "attr": 1})
+
+
+@validate_log_events([{"message.attr": 1}])
+@validate_log_event_count(1)
+@background_task()
+def test_logging_dict_attributes_only(logger):
+    logger.error({"attr": 1})

tests/logger_logging/test_local_decorating.py

@@ -35,10 +35,10 @@ def set_trace_ids():
         trace.guid = "abcdefgh"
 
 
-def exercise_logging(logger):
+def exercise_logging(logger, message="C"):
     set_trace_ids()
 
-    logger.warning("C")
+    logger.warning(message)
 
 
 def get_metadata_string(log_message, is_txn):
@@ -82,3 +82,14 @@ 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()

tests/logger_logging/test_log_forwarding.py

@@ -14,14 +14,19 @@
 
 import logging
 
-from newrelic.api.background_task import background_task
-from newrelic.api.time_trace import current_trace
-from newrelic.api.transaction import current_transaction
 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
+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 testing_support.validators.validate_log_events_outside_transaction import (
+    validate_log_events_outside_transaction,
+)
+
+from newrelic.api.background_task import background_task
+from newrelic.api.time_trace import current_trace
+from newrelic.api.transaction import current_transaction
 
 
 def set_trace_ids():
@@ -32,23 +37,30 @@ def set_trace_ids():
     if trace:
         trace.guid = "abcdefgh"
 
+
 def exercise_logging(logger):
     set_trace_ids()
 
     logger.debug("A")
     logger.info("B")
     logger.warning("C")
     logger.error("D")
-    logger.critical("E")
-    
+    logger.critical({"message": "E"})
+
     assert len(logger.caplog.records) == 3
 
+
 def update_all(events, attrs):
     for event in events:
         event.update(attrs)
 
 
-_common_attributes_service_linking = {"timestamp": None, "hostname": None, "entity.name": "Python Agent Test (logger_logging)", "entity.guid": None}
+_common_attributes_service_linking = {
+    "timestamp": None,
+    "hostname": None,
+    "entity.name": "Python Agent Test (logger_logging)",
+    "entity.guid": None,
+}
 _common_attributes_trace_linking = {"span.id": "abcdefgh", "trace.id": "abcdefgh12345678"}
 _common_attributes_trace_linking.update(_common_attributes_service_linking)
 
@@ -60,14 +72,11 @@ def update_all(events, attrs):
 update_all(_test_logging_inside_transaction_events, _common_attributes_trace_linking)
 
 
+@validate_log_events(_test_logging_inside_transaction_events)
+@validate_log_event_count(3)
+@background_task()
 def test_logging_inside_transaction(logger):
-    @validate_log_events(_test_logging_inside_transaction_events)
-    @validate_log_event_count(3)
-    @background_task()
-    def test():
-        exercise_logging(logger)
-
-    test()
+    exercise_logging(logger)
 
 
 _test_logging_outside_transaction_events = [
@@ -79,13 +88,10 @@ def test():
 
 
 @reset_core_stats_engine()
+@validate_log_events_outside_transaction(_test_logging_outside_transaction_events)
+@validate_log_event_count_outside_transaction(3)
 def test_logging_outside_transaction(logger):
-    @validate_log_events_outside_transaction(_test_logging_outside_transaction_events)
-    @validate_log_event_count_outside_transaction(3)
-    def test():
-        exercise_logging(logger)
-
-    test()
+    exercise_logging(logger)
 
 
 @reset_core_stats_engine()