Loguru Attribute Instrumentation (#1025)

* Add tests for logging's json logging

* Upgrade record_log_event to handle dict logging

* Update logging to capture dict messages

* Add attributes for dict log messages

* Implementation of JSON message filtering

* Correct attributes only log behavior

* Testing for logging attributes

* Add logging context test for py2

* Logically separate attribute tests

* Clean out imports

* Fix failing tests

* Structlog cleanup

* Attempting list instrumentation

* Structlog attributes support

Co-authored-by: Lalleh Rafeei <lrafeei@users.noreply.github.com>
Co-authored-by: Uma Annamalai <umaannamalai@users.noreply.github.com>

* Loguru instrumentation refactor

* New attribute testing

* Move exception settings

* Clean up testing

* Remove unneeded option

* Remove other framework changes

* [Mega-Linter] Apply linters fixes

* Bump tests

---------

Co-authored-by: Lalleh Rafeei <lrafeei@users.noreply.github.com>
Co-authored-by: Uma Annamalai <umaannamalai@users.noreply.github.com>
Co-authored-by: TimPansino <TimPansino@users.noreply.github.com>
Co-authored-by: mergify[bot] <37929162+mergify[bot]@users.noreply.github.com>

newrelic/hooks/logger_loguru.py

@@ -18,19 +18,24 @@
 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.package_version_utils import get_package_version_tuple
 from newrelic.common.signature import bind_args
 from newrelic.core.config import global_settings
 from newrelic.hooks.logger_logging import add_nr_linking_metadata
-from newrelic.packages import six
 
 _logger = logging.getLogger(__name__)
-is_pypy = hasattr(sys, "pypy_version_info")
 
+IS_PYPY = hasattr(sys, "pypy_version_info")
+LOGURU_VERSION = get_package_version_tuple("loguru")
+LOGURU_FILTERED_RECORD_ATTRS = {"extra", "message", "time", "level", "_nr_original_message", "record"}
+ALLOWED_LOGURU_OPTIONS_LENGTHS = frozenset((8, 9))
 
-def loguru_version():
-    from loguru import __version__
 
-    return tuple(int(x) for x in __version__.split("."))
+def _filter_record_attributes(record):
+    attrs = {k: v for k, v in record.items() if k not in LOGURU_FILTERED_RECORD_ATTRS}
+    extra_attrs = dict(record.get("extra", {}))
+    attrs.update({"extra.%s" % k: v for k, v in extra_attrs.items()})
+    return attrs
 
 
 def _nr_log_forwarder(message_instance):
@@ -59,17 +64,17 @@ def _nr_log_forwarder(message_instance):
                     application.record_custom_metric("Logging/lines/%s" % level_name, {"count": 1})
 
         if settings.application_logging.forwarding and settings.application_logging.forwarding.enabled:
-            attrs = dict(record.get("extra", {}))
+            attrs = _filter_record_attributes(record)
 
             try:
-                record_log_event(message, level_name, int(record["time"].timestamp()), attributes=attrs)
+                time = record.get("time", None)
+                if time:
+                    time = int(time.timestamp())
+                record_log_event(message, level_name, time, attributes=attrs)
             except Exception:
                 pass
 
 
-ALLOWED_LOGURU_OPTIONS_LENGTHS = frozenset((8, 9))
-
-
 def wrap_log(wrapped, instance, args, kwargs):
     try:
         bound_args = bind_args(wrapped, args, kwargs)
@@ -80,7 +85,7 @@ def wrap_log(wrapped, instance, args, kwargs):
         # Loguru looks into the stack trace to find the caller's module and function names.
         # options[1] tells loguru how far up to look in the stack trace to find the caller.
         # Because wrap_log is an extra call in the stack trace, loguru needs to look 1 level higher.
-        if not is_pypy:
+        if not IS_PYPY:
             options[1] += 1
         else:
             # PyPy inspection requires an additional frame of offset, as the wrapt internals seem to
@@ -111,7 +116,7 @@ def _nr_log_patcher(record):
                 record["_nr_original_message"] = message = record["message"]
                 record["message"] = add_nr_linking_metadata(message)
 
-    if loguru_version() > (0, 6, 0):
+    if LOGURU_VERSION > (0, 6, 0):
         if original_patcher is not None:
             patchers = [p for p in original_patcher]  # Consumer iterable into list so we can modify
             # Wipe out reference so patchers aren't called twice, as the framework will handle calling other patchers.
@@ -137,7 +142,7 @@ def patch_loguru_logger(logger):
             logger.add(_nr_log_forwarder, format="{message}")
             logger._core._nr_instrumented = True
     elif not hasattr(logger, "_nr_instrumented"):  # pragma: no cover
-        for _, handler in six.iteritems(logger._handlers):
+        for _, handler in logger._handlers.items():
             if handler._writer is _nr_log_forwarder:
                 logger._nr_instrumented = True
                 return

tests/logger_loguru/conftest.py

@@ -30,6 +30,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,
 }
 
@@ -58,7 +59,8 @@ def logger():
     import loguru
 
     _logger = loguru.logger
-    _logger.configure(extra={"global_extra": "global_value"})
+    _logger.configure(extra={"global_extra": 3})
+    _logger = _logger.opt(record=True)
 
     caplog = CaplogHandler()
     handler_id = _logger.add(caplog, level="WARNING", format="{message}")

tests/logger_loguru/test_attributes.py

@@ -0,0 +1,70 @@
+# 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.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
+
+
+@validate_log_events(
+    [
+        {  # Fixed attributes
+            "message": "context_attrs: arg1",
+            "context.file": "(name='%s', path='%s')" % ("test_attributes.py", str(__file__)),
+            "context.function": "test_loguru_default_context_attributes",
+            "context.extra.bound_attr": 1,
+            "context.extra.contextual_attr": 2,
+            "context.extra.global_extra": 3,
+            "context.extra.kwarg_attr": 4,
+            "context.patched_attr": 5,
+            "context.module": "test_attributes",
+            "context.name": "test_attributes",
+        }
+    ],
+    required_attrs=[  # Variable attributes
+        "context.elapsed",
+        "context.line",
+        "context.process",
+        "context.thread",
+    ],
+)
+@validate_log_event_count(1)
+@background_task()
+def test_loguru_default_context_attributes(logger):
+    def _patcher(d):
+        d["patched_attr"] = 5
+        return d
+
+    bound_logger = logger.bind(bound_attr=1)
+    bound_logger = bound_logger.patch(_patcher)
+    with bound_logger.contextualize(contextual_attr=2):
+        bound_logger.error("context_attrs: {}", "arg1", kwarg_attr=4)
+
+
+@validate_log_events([{"message": "exc_info"}], required_attrs=["context.exception"])
+@validate_log_event_count(1)
+@background_task()
+def test_loguru_exception_context_attributes(logger):
+    try:
+        raise RuntimeError("Oops")
+    except Exception:
+        logger.error("exc_info")
+
+
+@validate_log_events([{"context.extra.attr": 1}])
+@validate_log_event_count(1)
+@background_task()
+def test_loguru_attributes_only(logger):
+    logger.error("", attr=1)