fix: dedupe filter drop reports by rendered message (#1099)

mloda/core/filter/global_filter.py

@@ -74,9 +74,9 @@ def __init__(self) -> None:
         self.matched_filter_uuids: set[UUID] = set()
         self._warned_divergences: set[str] = set()
         # Own state, not dropped_filters: a falsy non-bool is an ordinary non-match, never a recorded drop.
-        self._reported_falsy_matches: set[tuple[type[FeatureGroup], str]] = set()
-        # WARNING dedupe for defect drops; the ledger itself no longer decides first-ness.
-        self._warned_drops: set[tuple[type[FeatureGroup], str]] = set()
+        self._reported_falsy_matches: set[str] = set()
+        # WARNING dedupe is based on the rendered line, while the ledger keeps per-declaration state.
+        self._warned_drops: set[str] = set()
 
     def reset_match_tracking(self) -> None:
         """Every match report is scoped to one engine setup, so a later setup names only what it consulted.
@@ -366,37 +366,31 @@ def _record_rejected_filter(
         )
 
     def _record_dropped_filter(self, feature_group: type[FeatureGroup], filter_feature_name: str, reason: str) -> None:
-        """Record the drop: defect drops warn once per key and take the key from a stored near-miss."""
+        """Record the drop: each distinct rendered report warns once."""
         key = (feature_group, filter_feature_name)
-        first = key not in self._warned_drops
-        self._warned_drops.add(key)
+        message = (
+            f"{feature_group.get_class_name()} {reason} while matching filter feature '{filter_feature_name}'; "
+            "dropping that filter for this feature group."
+        )
+        first = message not in self._warned_drops
+        self._warned_drops.add(message)
         if first:
             self.dropped_filters[key] = Elimination(stage="matcher_error", reason=reason)
-        logger.log(
-            logging.WARNING if first else logging.DEBUG,
-            "%s %s while matching filter feature '%s'; dropping that filter for this feature group.",
-            feature_group.get_class_name(),
-            reason,
-            filter_feature_name,
-        )
+        logger.log(logging.WARNING if first else logging.DEBUG, message)
 
     def _report_falsy_match(self, feature_group: type[FeatureGroup], filter_feature_name: str, returned: Any) -> None:
-        """Report the detached filter: WARNING on a key's first report, DEBUG after, like `_record_dropped_filter`.
+        """Report the detached filter: each distinct rendered line warns once, like `_record_dropped_filter`.
 
         Both fields are plugin-owned reads and this runs past the hook call's containment, so each degrades alone.
         """
-        key = (feature_group, filter_feature_name)
-        first = key not in self._reported_falsy_matches
-        self._reported_falsy_matches.add(key)
-        logger.log(
-            logging.WARNING if first else logging.DEBUG,
-            "%s returned a falsy non-bool (%s) while matching filter feature '%s'; that filter is not attached. "
-            "Return True explicitly to keep it.",
-            safe_field(lambda: feature_group.get_class_name(), "<unnamed feature group>"),
-            # The type name only: the value's own __repr__ is plugin code and must not run here.
-            safe_field(lambda: type(returned).__name__, "<unreadable type>"),
-            filter_feature_name,
+        message = (
+            f"{safe_field(lambda: feature_group.get_class_name(), '<unnamed feature group>')} returned a falsy "
+            f"non-bool ({safe_field(lambda: type(returned).__name__, '<unreadable type>')}) while matching filter "
+            f"feature '{filter_feature_name}'; that filter is not attached. Return True explicitly to keep it."
         )
+        first = message not in self._reported_falsy_matches
+        self._reported_falsy_matches.add(message)
+        logger.log(logging.WARNING if first else logging.DEBUG, message)
 
     def domain(self, filter: SingleFilter, feature_domain: None | Domain, feature_group: type[FeatureGroup]) -> bool:
         # We have matched already the feature group and the feature.

tests/test_core/test_filter/test_global_filter.py

@@ -1,4 +1,5 @@
 from datetime import datetime, timedelta, timezone
+import logging
 from typing import Any
 
 import pytest
@@ -52,6 +53,38 @@ def test_filter_config_empty(self) -> None:
         """Test that the GlobalFilter starts with an empty config."""
         assert len(self.global_filter.filters) == 0
 
+    def test_drop_reports_dedupe_by_rendered_message(self, caplog: pytest.LogCaptureFixture) -> None:
+        class ExampleFeatureGroup:
+            @classmethod
+            def get_class_name(cls) -> str:
+                return "ExampleFeatureGroup"
+
+        caplog.set_level(logging.DEBUG)
+
+        self.global_filter._record_dropped_filter(ExampleFeatureGroup, "age", "reason one")
+        self.global_filter._record_dropped_filter(ExampleFeatureGroup, "age", "reason two")
+        self.global_filter._record_dropped_filter(ExampleFeatureGroup, "age", "reason two")
+
+        records = [record for record in caplog.records if "dropping that filter" in record.message]
+        assert [record.levelno for record in records] == [logging.WARNING, logging.WARNING, logging.DEBUG]
+
+    def test_falsy_reports_dedupe_by_rendered_message_and_reset(self, caplog: pytest.LogCaptureFixture) -> None:
+        class ExampleFeatureGroup:
+            @classmethod
+            def get_class_name(cls) -> str:
+                return "ExampleFeatureGroup"
+
+        caplog.set_level(logging.DEBUG)
+
+        self.global_filter._report_falsy_match(ExampleFeatureGroup, "age", None)
+        self.global_filter._report_falsy_match(ExampleFeatureGroup, "age", None)
+        self.global_filter._report_falsy_match(ExampleFeatureGroup, "age", "")
+        self.global_filter.reset_match_tracking()
+        self.global_filter._report_falsy_match(ExampleFeatureGroup, "age", None)
+
+        records = [record for record in caplog.records if "filter is not attached" in record.message]
+        assert [record.levelno for record in records] == [logging.WARNING, logging.DEBUG, logging.WARNING, logging.WARNING]
+
 
 class TestGlobalFilterTimeTravel:
     def setup_method(self) -> None: