Add entry to subevent log when filtering out recipient

corehq/apps/sms/models.py

@@ -1069,6 +1069,7 @@ class MessagingEvent(models.Model, MessagingStatusMixin):
     ERROR_FCM_NO_ACTION = "FCM_NO_ACTION"
     ERROR_FCM_NOTIFICATION_FAILURE = "FCM_NOTIFICATION_FAILURE"
     ERROR_FCM_DOMAIN_NOT_ENABLED = 'FCM_DOMAIN_NOT_ENABLED'
+    FILTER_MISMATCH = 'FILTER_MISMATCH'
 
     ERROR_MESSAGES = {
         ERROR_NO_RECIPIENT:
@@ -1130,6 +1131,7 @@ class MessagingEvent(models.Model, MessagingStatusMixin):
         ERROR_FCM_NO_ACTION: gettext_noop("No action selected for the FCM Data message type."),
         ERROR_FCM_NOTIFICATION_FAILURE: gettext_noop("Failure while sending FCM notifications to the devices."),
         ERROR_FCM_DOMAIN_NOT_ENABLED: gettext_noop("Domain is not enabled for FCM Push Notifications"),
+        FILTER_MISMATCH: gettext_noop("Recipient did not match filters")
     }
 
     domain = models.CharField(max_length=126, null=False, db_index=True)

corehq/messaging/scheduling/scheduling_partitioned/models.py

@@ -260,29 +260,31 @@ def _get_filter_value(self, filter_value_or_property_name):
 
     def _passes_user_data_filter(self, contact):
         if not isinstance(contact, CouchUser):
-            return True
+            return True, ""
 
         if not self.memoized_schedule.user_data_filter:
-            return True
+            return True, ""
 
         if self.memoized_schedule.use_user_case_for_filter:
             user_case = contact.get_usercase_by_domain(self.domain)
             if user_case:
                 user_data = user_case.case_json
             else:
-                return False
+                return False, "No user case to filter on"
         else:
             user_data = contact.get_user_data(self.domain)
         for key, value_or_property_name in self.memoized_schedule.user_data_filter.items():
             allowed_values_set = {self._get_filter_value(v) for v in self.convert_to_set(value_or_property_name)}
             actual_values_set = self.convert_to_set(user_data.get(key, ""))
 
             if actual_values_set.isdisjoint(allowed_values_set):
-                return False
+                return False, (f"Filtered out on property {key}: "
+                               f"allowed: ({','.join(allowed_values_set)}), "
+                               f"found: ({','.join(actual_values_set)})")
 
-        return True
+        return True, ""
 
-    def expand_recipients(self):
+    def expand_recipients(self, handle_filtered_recipient=None):
         """
         Can be used as a generator to iterate over all individual contacts who
         are the recipients of this ScheduleInstance.
@@ -293,8 +295,11 @@ def expand_recipients(self):
 
         for member in recipient_list:
             for contact in self._expand_recipient(member):
-                if self._passes_user_data_filter(contact):
+                passed, filter_reason = self._passes_user_data_filter(contact)
+                if passed:
                     yield contact
+                elif handle_filtered_recipient is not None:
+                    handle_filtered_recipient(contact, filter_reason)
 
     def get_content_send_lock(self, recipient):
         if is_commcarecase(recipient):
@@ -334,8 +339,15 @@ def send_current_event_content_to_recipients(self):
 
         logged_event = MessagingEvent.create_from_schedule_instance(self, content)
 
+        def log_filtered_recipient(filtered_recipient, reason):
+            sub_event = logged_event.create_subevent_from_contact_and_content(
+                filtered_recipient,
+                content,
+            )
+            sub_event.error(MessagingEvent.FILTER_MISMATCH, reason)
+
         recipient_count = 0
-        for recipient in self.expand_recipients():
+        for recipient in self.expand_recipients(log_filtered_recipient):
             recipient_count += 1
 
             #   The framework will retry sending a non-processed schedule instance

corehq/messaging/scheduling/tests/test_recipients.py

@@ -117,15 +117,19 @@ def test_fails_with_user_data_filter_because_value_does_not_match(self):
         schedule = AlertSchedule()
         schedule.use_user_case_for_filter = False
         schedule.user_data_filter = {"wants_email": ["no"]}
-        self.assertFalse(ScheduleInstance(domain=self.domain, schedule=schedule)
-                         ._passes_user_data_filter(self.mobile_user))
+        passed, msg = (ScheduleInstance(domain=self.domain, schedule=schedule).
+                       _passes_user_data_filter(self.mobile_user))
+        self.assertFalse(passed)
+        self.assertEqual(msg, "Filtered out on property wants_email: allowed: (no), found: (yes)")
 
     def test_fails_with_user_data_filter_because_one_value_does_not_match(self):
         schedule = AlertSchedule()
         schedule.use_user_case_for_filter = False
         schedule.user_data_filter = {"wants_email": ["yes"], "color": ["red"]}
-        self.assertFalse(ScheduleInstance(domain=self.domain, schedule=schedule)
-                         ._passes_user_data_filter(self.mobile_user))
+        passed, msg = (ScheduleInstance(domain=self.domain, schedule=schedule).
+                       _passes_user_data_filter(self.mobile_user))
+        self.assertFalse(passed)
+        self.assertEqual(msg, "Filtered out on property color: allowed: (red), found: (green)")
 
     def test_passes_with_user_case_filter(self):
         case = create_case_2(self.domain, case_type="thing", case_json={"case_color": "green"})
@@ -154,8 +158,10 @@ def test_fails_if_filter_on_case_but_no_case(self):
         schedule = AlertSchedule()
         schedule.use_user_case_for_filter = True
         schedule.user_data_filter = {"wants_email": ["yes"]}
-        self.assertFalse(ScheduleInstance(schedule=schedule)
-                        ._passes_user_data_filter(self.mobile_user))
+        passed, msg = (ScheduleInstance(schedule=schedule).
+                       _passes_user_data_filter(self.mobile_user))
+        self.assertFalse(passed)
+        self.assertEqual("No user case to filter on", msg)
 
 
 @es_test(requires=[user_adapter], setup_class=True)
@@ -687,10 +693,21 @@ def test_mobile_worker_recipients_with_user_data_filter(self):
             recipient_type='Group',
             recipient_id=self.group2.get_id
         )
+        message = ""
+        filtered_count = 0
+
+        def handle_filtered_recipient(_, msg):
+            nonlocal message
+            nonlocal filtered_count
+            message = msg
+            filtered_count += 1
+
         self.assertEqual(
-            self.user_ids(instance.expand_recipients()),
+            self.user_ids(instance.expand_recipients(handle_filtered_recipient)),
             [self.mobile_user4.get_id, self.mobile_user5.get_id, self.mobile_user6.get_id]
         )
+        self.assertEqual(message, "Filtered out on property role: allowed: (nurse), found: (pharmacist)")
+        self.assertEqual(2, filtered_count)
 
     def test_web_user_recipient_with_user_data_filter(self):
         schedule = self._create_schedule(user_data_filter={'role': ['nurse']})