Add builtin logging framework instrumentation. (#549)

* Add logging instrumentation

Uma Annamalai umaannamalai@users.noreply.github.com

* Address code review comments.

* Fix testing failures

Co-authored-by: Timothy Pansino <11214426+TimPansino@users.noreply.github.com>
Co-authored-by: Tim Pansino <timpansino@gmail.com>

newrelic/api/import_hook.py

@@ -40,6 +40,7 @@
     # These modules should not be added to the _uninstrumented_modules set
     # because they have been deemed okay to import before initialization by
     # the customer.
+    "logging",
     "gunicorn.app.base",
     "wsgiref.simple_server",
     "gevent.wsgi",

newrelic/config.py

@@ -2307,6 +2307,12 @@ def _process_module_builtin_defaults():
         "instrument_cherrypy__cptree",
     )
 
+    _process_module_definition(
+        "logging",
+        "newrelic.hooks.logger_logging",
+        "instrument_logging",
+    )
+
     _process_module_definition(
         "paste.httpserver",
         "newrelic.hooks.adapter_paste",

newrelic/hooks/logger_logging.py

@@ -0,0 +1,93 @@
+# 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 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 wrap_function_wrapper, function_wrapper
+from newrelic.core.config import global_settings
+
+
+try:
+    from urllib import quote
+except ImportError:
+    from urllib.parse import quote
+
+
+def add_nr_linking_metadata(message):
+    available_metadata = get_linking_metadata()
+    entity_name = quote(available_metadata.get("entity.name", ""))
+    entity_guid = available_metadata.get("entity.guid", "") 
+    span_id = available_metadata.get("span.id", "")
+    trace_id = available_metadata.get("trace.id", "")
+    hostname = available_metadata.get("hostname", "")
+
+    nr_linking_str = "|".join(("NR-LINKING", entity_guid, hostname, trace_id, span_id, entity_name))
+    return "%s %s|" % (message, nr_linking_str)
+
+
+@function_wrapper
+def wrap_getMessage(wrapped, instance, args, kwargs):
+    message = wrapped(*args, **kwargs)
+    return add_nr_linking_metadata(message)
+
+
+def bind_callHandlers(record):
+    return record
+
+
+def wrap_callHandlers(wrapped, instance, args, kwargs):
+    transaction = current_transaction()
+    record = bind_callHandlers(*args, **kwargs)
+
+    logger_name = getattr(instance, "name", None)
+    if logger_name and logger_name.split(".")[0] == "newrelic":
+        return wrapped(*args, **kwargs)
+
+    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_name = str(getattr(record, "levelname", "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:
+                message = record.getMessage()
+                record_log_event(message, level_name, int(record.created * 1000))
+            except Exception:
+                pass
+
+        if settings.application_logging.local_decorating and settings.application_logging.local_decorating.enabled:
+            record._nr_original_message = record.getMessage
+            record.getMessage = wrap_getMessage(record.getMessage)
+
+    return wrapped(*args, **kwargs)
+
+
+def instrument_logging(module):
+    if hasattr(module, "Logger"):
+        if hasattr(module.Logger, "callHandlers"):
+            wrap_function_wrapper(module, "Logger.callHandlers", wrap_callHandlers)

tests/agent_features/test_collector_payloads.py

@@ -12,6 +12,7 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
+import pytest
 import webtest
 
 from testing_support.fixtures import (validate_error_trace_collector_json,
@@ -22,6 +23,8 @@
 from testing_support.sample_applications import (simple_app,
         simple_exceptional_app, simple_custom_event_app)
 
+from testing_support.validators.validate_log_event_collector_json import validate_log_event_collector_json
+
 
 exceptional_application = webtest.TestApp(simple_exceptional_app)
 normal_application = webtest.TestApp(simple_app)
@@ -63,3 +66,10 @@ def test_transaction_event_json():
 @validate_custom_event_collector_json()
 def test_custom_event_json():
     custom_event_application.get('/')
+
+
+@pytest.mark.xfail(reason="Unwritten validator")
+@validate_log_event_collector_json
+def test_log_event_json():
+    normal_application.get('/')
+    raise NotImplementedError("Fix my validator")

tests/logger_logging/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_logging",
+]
+
+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_logging)",
+    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():
+    _logger = logging.getLogger("my_app")
+    caplog = CaplogHandler()
+    _logger.addHandler(caplog)
+    _logger.caplog = caplog
+    _logger.setLevel(logging.WARNING)
+    yield _logger
+    del caplog.records[:]
+    _logger.removeHandler(caplog)

tests/logger_logging/test_local_decorating.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.
+
+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
+
+
+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()[1]
+    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_logging%29|'))
+    else:
+        metadata_string = "".join(('NR-LINKING|', entity_guid, '|', host, '|||Python%20Agent%20Test%20%28logger_logging%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()

tests/logger_logging/test_log_forwarding.py

@@ -0,0 +1,101 @@
+# 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.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_events import validate_log_events
+from testing_support.validators.validate_log_events_outside_transaction import validate_log_events_outside_transaction
+
+
+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.debug("A")
+    logger.info("B")
+    logger.warning("C")
+    logger.error("D")
+    logger.critical("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_trace_linking = {"span.id": "abcdefgh", "trace.id": "abcdefgh12345678"}
+_common_attributes_trace_linking.update(_common_attributes_service_linking)
+
+_test_logging_inside_transaction_events = [
+    {"message": "C", "level": "WARNING"},
+    {"message": "D", "level": "ERROR"},
+    {"message": "E", "level": "CRITICAL"},
+]
+update_all(_test_logging_inside_transaction_events, _common_attributes_trace_linking)
+
+
+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()
+
+
+_test_logging_outside_transaction_events = [
+    {"message": "C", "level": "WARNING"},
+    {"message": "D", "level": "ERROR"},
+    {"message": "E", "level": "CRITICAL"},
+]
+update_all(_test_logging_outside_transaction_events, _common_attributes_service_linking)
+
+
+@reset_core_stats_engine()
+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()
+
+
+@reset_core_stats_engine()
+def test_logging_newrelic_logs_not_forwarded(logger):
+    @validate_log_event_count(0)
+    @background_task()
+    def test():
+        nr_logger = logging.getLogger("newrelic")
+        nr_logger.addHandler(logger.caplog)
+        nr_logger.error("A")
+        assert len(logger.caplog.records) == 1
+
+    test()