Fix notice_error Rules Matching Settings Handling (#383)

* Remove active traces from tests to expose bug

* Handle settings passing in error matching rules

* Better edge case handling

* Apply linter fixes

* Correct settings origin to transaction

* Change logs in context expected errors

* Apply linters fixes

Author: TimPansino

newrelic/api/log.py

@@ -13,23 +13,28 @@
 # limitations under the License.
 
 import json
-from newrelic.common.object_names import parse_exc_info
-import newrelic.packages.six as six
 from logging import Formatter, LogRecord
+
 from newrelic.api.time_trace import get_linking_metadata
+from newrelic.common.object_names import parse_exc_info
 from newrelic.core.config import is_expected_error
 
 
 def format_exc_info(exc_info):
     _, _, fullnames, message = parse_exc_info(exc_info)
     fullname = fullnames[0]
 
-    return {
+    formatted = {
         "error.class": fullname,
         "error.message": message,
-        "error.expected": is_expected_error(exc_info),
     }
 
+    expected = is_expected_error(exc_info)
+    if expected is not None:
+        formatted["error.expected"] = expected
+
+    return formatted
+
 
 class NewRelicContextFormatter(Formatter):
     DEFAULT_LOG_RECORD_KEYS = frozenset(vars(LogRecord("", 0, "", 0, "", (), None)))
@@ -57,7 +62,7 @@ def log_record_to_dict(cls, record):
         if len(record.__dict__) > len(DEFAULT_LOG_RECORD_KEYS):
             for key in record.__dict__:
                 if key not in DEFAULT_LOG_RECORD_KEYS:
-                    output['extra.' + key] = getattr(record, key)
+                    output["extra." + key] = getattr(record, key)
 
         if record.exc_info:
             output.update(format_exc_info(record.exc_info))
@@ -72,4 +77,4 @@ def safe_str(object, *args, **kwargs):
             except:
                 return "<unprintable %s object>" % type(object).__name__
 
-        return json.dumps(self.log_record_to_dict(record), default=safe_str, separators=(',', ':'))
+        return json.dumps(self.log_record_to_dict(record), default=safe_str, separators=(",", ":"))

newrelic/api/time_trace.py

@@ -221,9 +221,9 @@ def _observe_exception(self, exc_info=None, ignore=None, expected=None, status_c
         if not exc_info or None in exc_info:
             exc_info = sys.exc_info()
 
-        # If no exception to report, exit
-        if not exc_info or None in exc_info:
-            return
+            # If no exception to report, exit
+            if not exc_info or None in exc_info:
+                return
 
         exc, value, tb = exc_info
 
@@ -281,7 +281,7 @@ def _observe_exception(self, exc_info=None, ignore=None, expected=None, status_c
 
         # Default rule matching
         if should_ignore is None:
-            should_ignore = should_ignore_error(exc_info, status_code=status_code)
+            should_ignore = should_ignore_error(exc_info, status_code=status_code, settings=settings)
             if should_ignore:
                 return
 
@@ -304,7 +304,7 @@ def _observe_exception(self, exc_info=None, ignore=None, expected=None, status_c
 
         # Default rule matching
         if is_expected is None:
-            is_expected = is_expected_error(exc_info, status_code=status_code)
+            is_expected = is_expected_error(exc_info, status_code=status_code, settings=settings)
 
         # Record a supportability metric if error attributes are being
         # overiden.

newrelic/api/transaction.py

@@ -390,6 +390,11 @@ def __exit__(self, exc, value, tb):
         if not self._settings:
             return
 
+        # Record error if one was registered.
+
+        if exc is not None and value is not None and tb is not None:
+            self.root_span.notice_error((exc, value, tb))
+
         self._state = self.STATE_STOPPED
 
         # Force the root span out of the cache if it's there
@@ -418,11 +423,6 @@ def __exit__(self, exc, value, tb):
             )
             return
 
-        # Record error if one was registered.
-
-        if exc is not None and value is not None and tb is not None:
-            root.notice_error((exc, value, tb))
-
         # Record the end time for transaction and then
         # calculate the duration.
 
@@ -937,7 +937,7 @@ def user_attributes(self):
     def _compute_sampled_and_priority(self):
         if self._priority is None:
             # truncate priority field to 6 digits past the decimal
-            self._priority = float("%.6f" % random.random())
+            self._priority = float("%.6f" % random.random())  # nosec
 
         if self._sampled is None:
             self._sampled = self._application.compute_sampled()

newrelic/core/config.py

@@ -41,8 +41,8 @@
 try:
     import grpc
 
-    from newrelic.core.infinite_tracing_pb2 import (
-        Span as _,  # NOQA # pylint: disable=W0611,C0412
+    from newrelic.core.infinite_tracing_pb2 import (  # pylint: disable=W0611,C0412  # noqa: F401
+        Span,
     )
 except ImportError:
     grpc = None
@@ -1034,13 +1034,12 @@ def apply_server_side_settings(server_side_config=None, settings=_settings):
     apply_config_setting(settings_snapshot, "event_harvest_config.whitelist", frozenset(harvest_limits))
 
     # Override span event harvest config
-    span_event_harvest_config = server_side_config.get('span_event_harvest_config', {})
+    span_event_harvest_config = server_side_config.get("span_event_harvest_config", {})
     span_event_harvest_limit = span_event_harvest_config.get("harvest_limit", None)
     if span_event_harvest_limit is not None:
         apply_config_setting(
-                settings_snapshot,
-                'event_harvest_config.harvest_limits.span_event_data',
-                span_event_harvest_limit)
+            settings_snapshot, "event_harvest_config.harvest_limits.span_event_data", span_event_harvest_limit
+        )
 
     # This will be removed at some future point
     # Special case for account_id which will be sent instead of
@@ -1103,53 +1102,71 @@ def ignore_status_code(status):
 def is_expected_error(
     exc_info,
     status_code=None,
+    settings=None,
 ):
+    """Check if an error is expected based on rules matching. Default is False when settings lookup fails."""
     return error_matches_rules(
         "expected",
         exc_info,
         status_code=status_code,
+        settings=settings,
     )
 
 
 def should_ignore_error(
     exc_info,
     status_code=None,
+    settings=None,
 ):
+    """Check if an error should be ignored based on rules matching. Default is True when settings lookup fails."""
     return error_matches_rules(
         "ignore",
         exc_info,
         status_code=status_code,
+        settings=settings,
     )
 
 
 def error_matches_rules(
     rules_prefix,
     exc_info,
     status_code=None,
+    settings=None,
 ):
+    """
+    Attempt to match exception to rules based on prefix.
+
+    rules_prefix is one of [ignore, expected]
+    exc_info is an exception tuple of (exc, val, tb)
+    status_code is an optional value or callable taking in exc_info that returns an int-like object
+    origin is either the current application or trace.
+    """
     # Delay imports to prevent lockups
-    from newrelic.api.application import application_instance
     from newrelic.core.trace_cache import trace_cache
 
-    trace = trace_cache().current_trace()
-    settings = trace and trace.settings
-
-    if not settings:
-        # Retrieve application settings
-        application = application_instance()
-        settings = application and application.settings
-
-    # Default to global settings
-    settings = settings or global_settings()
-
     if not settings:
-        return False
+        # Pull from current transaction if no settings provided
+        tc = trace_cache()
+        transaction = tc.current_transaction()
+        settings = transaction and transaction.settings
+
+        if not settings:
+            # Pull from active trace if no settings on transaction
+            trace = tc.current_trace()
+            settings = trace and trace.settings
+
+            if not settings:
+                # Unable to find rules to match with
+                _logger.error(
+                    "Failed to retrieve exception rules: No settings supplied, or found on transaction or trace."
+                )
+                return None
 
     # Retrieve settings based on prefix
     classes_rules = getattr(settings.error_collector, "%s_classes" % rules_prefix, set())
     status_codes_rules = getattr(settings.error_collector, "%s_status_codes" % rules_prefix, set())
 
-    module, name, fullnames, message = parse_exc_info(exc_info)
+    _, _, fullnames, _ = parse_exc_info(exc_info)
     fullname = fullnames[0]
 
     # Check class names

newrelic/core/stats_engine.py

@@ -316,7 +316,7 @@ def add(self, sample, priority=None):  # pylint: disable=E0202
         self.num_seen += 1
 
         if priority is None:
-            priority = random.random()
+            priority = random.random()  # nosec
 
         entry = (priority, self.num_seen, sample)
         if self.num_seen == self.capacity:
@@ -584,9 +584,9 @@ def notice_error(self, error=None, attributes=None, expected=None, ignore=None,
         if not error or None in error:
             error = sys.exc_info()
 
-        # If no exception to report, exit
-        if not error or None in error:
-            return
+            # If no exception to report, exit
+            if not error or None in error:
+                return
 
         exc, value, tb = error
 
@@ -637,7 +637,7 @@ def notice_error(self, error=None, attributes=None, expected=None, ignore=None,
 
         # Default rule matching
         if should_ignore is None:
-            should_ignore = should_ignore_error(error, status_code=status_code)
+            should_ignore = should_ignore_error(error, status_code=status_code, settings=settings)
             if should_ignore:
                 return
 
@@ -660,7 +660,7 @@ def notice_error(self, error=None, attributes=None, expected=None, ignore=None,
 
         # Default rule matching
         if is_expected is None:
-            is_expected = is_expected_error(error, status_code=status_code)
+            is_expected = is_expected_error(error, status_code=status_code, settings=settings)
 
         # Only add attributes if High Security Mode is off.
 

tests/agent_features/test_logs_in_context.py

@@ -113,7 +113,8 @@ class ExceptionForTest(ValueError):
     pass
 
 
-def test_newrelic_logger_error(log_buffer):
+@background_task()
+def test_newrelic_logger_error_inside_transaction(log_buffer):
     try:
         raise ExceptionForTest
     except ExceptionForTest:
@@ -134,7 +135,8 @@ def test_newrelic_logger_error(log_buffer):
     assert filename.endswith("/test_logs_in_context.py")
     assert isinstance(line_number, int)
 
-    assert message == {
+    expected = {
+        u"entity.name": u"Python Agent Test (agent_features)",
         u"entity.type": u"SERVICE",
         u"message": u"oops",
         u"log.level": u"ERROR",
@@ -145,6 +147,49 @@ def test_newrelic_logger_error(log_buffer):
         u"error.message": u"",
         u"error.expected": False,
     }
+    expected_extra_txn_keys = (
+        "trace.id",
+        "span.id",
+        "entity.guid",
+    )
+
+    for k, v in expected.items():
+        assert message.pop(k) == v
+
+    assert set(message.keys()) == set(expected_extra_txn_keys)
+
+
+def test_newrelic_logger_error_outside_transaction(log_buffer):
+    try:
+        raise ExceptionForTest
+    except ExceptionForTest:
+        _logger.exception(u"oops")
+
+    log_buffer.seek(0)
+    message = json.load(log_buffer)
+
+    timestamp = message.pop("timestamp")
+    thread_id = message.pop("thread.id")
+    process_id = message.pop("process.id")
+    filename = message.pop("file.name")
+    line_number = message.pop("line.number")
+
+    assert isinstance(timestamp, int)
+    assert isinstance(thread_id, int)
+    assert isinstance(process_id, int)
+    assert filename.endswith("/test_logs_in_context.py")
+    assert isinstance(line_number, int)
+
+    assert message == {
+        u"entity.type": u"SERVICE",
+        u"message": u"oops",
+        u"log.level": u"ERROR",
+        u"logger.name": u"test_logs_in_context",
+        u"thread.name": u"MainThread",
+        u"process.name": u"MainProcess",
+        u"error.class": u"test_logs_in_context:ExceptionForTest",
+        u"error.message": u"",
+    }
 
 
 EXPECTED_KEYS_TXN = (