Loguru Instrumentation (#552)

* Add loguru instrumentation

* Add more loguru versions to test

* Correct tox ini file

* Fix missing parenthesis

* Fix loguru v4 and add patching test

* Patch loguru v3 support

newrelic/config.py

@@ -2313,6 +2313,17 @@ def _process_module_builtin_defaults():
         "instrument_logging",
     )
 
+    _process_module_definition(
+        "loguru",
+        "newrelic.hooks.logger_loguru",
+        "instrument_loguru",
+    )
+    _process_module_definition(
+        "loguru._logger",
+        "newrelic.hooks.logger_loguru",
+        "instrument_loguru_logger",
+    )
+
     _process_module_definition(
         "paste.httpserver",
         "newrelic.hooks.adapter_paste",

newrelic/hooks/logger_loguru.py

@@ -0,0 +1,142 @@
+# 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
+
+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.core.config import global_settings
+from newrelic.hooks.logger_logging import add_nr_linking_metadata
+from newrelic.packages import six
+
+_logger = logging.getLogger(__name__) 
+
+def loguru_version():
+    from loguru import __version__
+    return tuple(int(x) for x in __version__.split("."))
+
+
+def _nr_log_forwarder(message_instance):
+    transaction = current_transaction()
+    record = message_instance.record
+    message = record.get("_nr_original_message", record["message"])
+
+    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:
+        level = record["level"]
+        level_name = "UNKNOWN" if not level else (level.name or "UNKNOWN")
+
+        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(message, level_name, int(record["time"].timestamp()))
+            except Exception:
+                pass
+
+
+ALLOWED_LOGURU_OPTIONS_LENGTHS = frozenset((8, 9))
+
+def bind_log(level_id, static_level_no, from_decorator, options, message, args, kwargs):
+    assert len(options) in ALLOWED_LOGURU_OPTIONS_LENGTHS  # Assert the options signature we expect
+    return level_id, static_level_no, from_decorator, list(options), message, args, kwargs
+
+
+def wrap_log(wrapped, instance, args, kwargs):
+    try:
+        level_id, static_level_no, from_decorator, options, message, subargs, subkwargs = bind_log(*args, **kwargs)
+        options[-2] = nr_log_patcher(options[-2])
+    except Exception as e:
+        _logger.debug("Exception in loguru handling: %s" % str(e))
+        return wrapped(*args, **kwargs)
+    else:
+        return wrapped(level_id, static_level_no, from_decorator, options, message, subargs, subkwargs)
+
+
+def nr_log_patcher(original_patcher=None):
+    def _nr_log_patcher(record):
+        if original_patcher:
+            record = original_patcher(record)
+
+        transaction = current_transaction()
+
+        if transaction:
+            settings = transaction.settings
+        else:
+            settings = global_settings()
+
+        if settings and settings.application_logging and settings.application_logging.enabled:
+            if settings.application_logging.local_decorating and settings.application_logging.local_decorating.enabled:
+                record["_nr_original_message"] = message = record["message"]
+                record["message"] = add_nr_linking_metadata(message)
+
+    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.
+            original_patcher = None
+        else:
+            patchers = []
+
+        patchers.append(_nr_log_patcher)
+        return patchers
+    else:
+        return _nr_log_patcher
+
+
+def wrap_Logger_init(wrapped, instance, args, kwargs):
+    result = wrapped(*args, **kwargs)
+    patch_loguru_logger(instance)
+    return result
+
+
+def patch_loguru_logger(logger):
+    if hasattr(logger, "_core"):
+        if not hasattr(logger._core, "_nr_instrumented"):
+            logger.add(_nr_log_forwarder, format="{message}")
+            logger._core._nr_instrumented = True
+    elif not hasattr(logger, "_nr_instrumented"):
+        for _, handler in six.iteritems(logger._handlers):
+            if handler._writer is _nr_log_forwarder:
+                logger._nr_instrumented = True
+                return
+
+        logger.add(_nr_log_forwarder, format="{message}")
+        logger._nr_instrumented = True
+
+
+def instrument_loguru_logger(module):
+    if hasattr(module, "Logger"):
+        wrap_function_wrapper(module, "Logger.__init__", wrap_Logger_init)
+        if hasattr(module.Logger, "_log"):
+            wrap_function_wrapper(module, "Logger._log", wrap_log)
+
+
+def instrument_loguru(module):
+    if hasattr(module, "logger"):
+        patch_loguru_logger(module.logger)

tests/logger_loguru/conftest.py

@@ -0,0 +1,71 @@
+# 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 testing_support.fixtures import (
+    code_coverage_fixture,
+    collector_agent_registration_fixture,
+    collector_available_fixture,
+)
+
+_coverage_source = [
+    "newrelic.hooks.logger_loguru",
+]
+
+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_loguru)",
+    default_settings=_default_settings,
+)
+
+
+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)
+
+    def emit(self, record):
+        self.records.append(self.format(record))
+
+
+@pytest.fixture(scope="function")
+def logger():
+    import loguru
+    _logger = loguru.logger
+    caplog = CaplogHandler()
+    handler_id = _logger.add(caplog, level="WARNING", format="{message}")
+    _logger.caplog = caplog
+    yield _logger
+    del caplog.records[:]
+    _logger.remove(handler_id)

tests/logger_loguru/test_local_decorating.py

@@ -0,0 +1,88 @@
+# 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 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.fixtures import (
+    validate_transaction_metrics,
+)
+
+
+def set_trace_ids():
+    txn = current_transaction()
+    if txn:
+        txn._trace_id = "abcdefgh12345678"
+    trace = current_trace()
+    if trace:
+        trace.guid = "abcdefgh"
+
+def exercise_logging(logger):
+    set_trace_ids()
+
+    logger.warning("C")
+
+
+def get_metadata_string(log_message, is_txn):
+    host = platform.uname().node
+    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_loguru%29|'))
+    else:
+        metadata_string = "".join(('NR-LINKING|', entity_guid, '|', host, '|||Python%20Agent%20Test%20%28logger_loguru%29|'))
+    formatted_string = log_message + " " + metadata_string
+    return formatted_string
+
+
+@reset_core_stats_engine()
+def test_local_log_decoration_inside_transaction(logger):
+    @validate_log_event_count(1)
+    @background_task()
+    def test():
+        exercise_logging(logger)
+        assert logger.caplog.records[0] == get_metadata_string('C', True)
+
+    test()
+
+
+@reset_core_stats_engine()
+def test_local_log_decoration_outside_transaction(logger):
+    @validate_log_event_count_outside_transaction(1)
+    def test():
+        exercise_logging(logger)
+        assert logger.caplog.records[0] == get_metadata_string('C', False)
+
+    test()
+
+
+@reset_core_stats_engine()
+def test_patcher_application_order(logger):
+    def patch(record):
+        record["message"] += "-PATCH"
+        return record
+
+    @validate_log_event_count_outside_transaction(1)
+    def test():
+        patch_logger = logger.patch(patch)
+        exercise_logging(patch_logger)
+        assert logger.caplog.records[0] == get_metadata_string('C-PATCH', False)
+
+    test()