Merge pull request #4573 from mozilla/more-complaint-bounce-logs-3784

MPP-3784: Add FxA ID to logs for bounces and complaints

emails/tests/views_tests.py

@@ -906,55 +906,136 @@ def test_ses_client_error(self) -> None:
         assert getattr(error_log, "Message") == "the message"
 
 
+@override_settings(STATSD_ENABLED=True)
 class BounceHandlingTest(TestCase):
     def setUp(self):
         self.user = baker.make(User, email="[email protected]")
+        self.sa: SocialAccount = baker.make(
+            SocialAccount, user=self.user, provider="fxa", uid=str(uuid4())
+        )
 
     def test_sns_message_with_hard_bounce(self) -> None:
         pre_request_datetime = datetime.now(timezone.utc)
 
-        _sns_notification(BOUNCE_SNS_BODIES["hard"])
+        with self.assertLogs(INFO_LOG) as logs, MetricsMock() as mm:
+            _sns_notification(BOUNCE_SNS_BODIES["hard"])
 
         self.user.refresh_from_db()
         assert self.user.profile.last_hard_bounce is not None
         assert self.user.profile.last_hard_bounce >= pre_request_datetime
 
+        assert len(logs.records) == 1
+        log_data = log_extra(logs.records[0])
+        assert (diagnostic := log_data["bounce_diagnostic"])
+        assert log_data == {
+            "bounce_action": "failed",
+            "bounce_diagnostic": diagnostic,
+            "bounce_status": "5.1.1",
+            "bounce_subtype": "OnAccountSuppressionList",
+            "bounce_type": "Permanent",
+            "domain": "test.com",
+            "relay_action": "hard_bounce",
+            "user_match": "found",
+            "fxa_id": self.sa.uid,
+        }
+
+        mm.assert_incr_once(
+            "fx.private.relay.email_bounce",
+            tags=[
+                "bounce_type:permanent",
+                "bounce_subtype:onaccountsuppressionlist",
+                "user_match:found",
+                "relay_action:hard_bounce",
+            ],
+        )
+
     def test_sns_message_with_soft_bounce(self) -> None:
         pre_request_datetime = datetime.now(timezone.utc)
 
-        _sns_notification(BOUNCE_SNS_BODIES["soft"])
+        with self.assertLogs(INFO_LOG) as logs, MetricsMock() as mm:
+            _sns_notification(BOUNCE_SNS_BODIES["soft"])
 
         self.user.refresh_from_db()
         assert self.user.profile.last_soft_bounce is not None
         assert self.user.profile.last_soft_bounce >= pre_request_datetime
 
+        assert len(logs.records) == 1
+        log_data = log_extra(logs.records[0])
+        assert (diagnostic := log_data["bounce_diagnostic"])
+        assert log_data == {
+            "bounce_action": "failed",
+            "bounce_diagnostic": diagnostic,
+            "bounce_status": "5.1.1",
+            "bounce_subtype": "SRETeamEatenByDinosaurs",
+            "bounce_type": "Transient",
+            "domain": "test.com",
+            "relay_action": "soft_bounce",
+            "user_match": "found",
+            "fxa_id": self.sa.uid,
+        }
+
+        mm.assert_incr_once(
+            "fx.private.relay.email_bounce",
+            tags=[
+                "bounce_type:transient",
+                "bounce_subtype:sreteameatenbydinosaurs",
+                "user_match:found",
+                "relay_action:soft_bounce",
+            ],
+        )
+
     def test_sns_message_with_spam_bounce_sets_auto_block_spam(self):
-        _sns_notification(BOUNCE_SNS_BODIES["spam"])
+        with self.assertLogs(INFO_LOG) as logs, MetricsMock() as mm:
+            _sns_notification(BOUNCE_SNS_BODIES["spam"])
         self.user.refresh_from_db()
         assert self.user.profile.auto_block_spam
 
+        assert len(logs.records) == 1
+        log_data = log_extra(logs.records[0])
+        assert (diagnostic := log_data["bounce_diagnostic"])
+        assert log_data == {
+            "bounce_action": "failed",
+            "bounce_diagnostic": diagnostic,
+            "bounce_status": "5.1.1",
+            "bounce_subtype": "StopRelayingSpamForThisUser",
+            "bounce_type": "Transient",
+            "domain": "test.com",
+            "relay_action": "auto_block_spam",
+            "user_match": "found",
+            "fxa_id": self.sa.uid,
+        }
 
-class ComplaintHandlingTest(TestCase):
-    """Test Complaint notifications and events."""
+        mm.assert_incr_once(
+            "fx.private.relay.email_bounce",
+            tags=[
+                "bounce_type:transient",
+                "bounce_subtype:stoprelayingspamforthisuser",
+                "user_match:found",
+                "relay_action:auto_block_spam",
+            ],
+        )
 
-    def setUp(self):
-        self.user = baker.make(User, email="[email protected]")
+    def test_sns_message_with_hard_bounce_and_optout(self) -> None:
+        self.sa.extra_data["metricsEnabled"] = False
+        self.sa.save()
 
-    @pytest.fixture(autouse=True)
-    def use_caplog(self, caplog):
-        self.caplog = caplog
+        with self.assertLogs(INFO_LOG) as logs:
+            _sns_notification(BOUNCE_SNS_BODIES["hard"])
 
-    @override_settings(STATSD_ENABLED=True)
-    def test_notification_type_complaint(self):
-        """
-        A notificationType of complaint increments a counter, logs details, and
-        returns 200.
+        log_data = log_extra(logs.records[0])
+        assert log_data["user_match"] == "found"
+        assert not log_data["fxa_id"]
 
-        Example derived from:
-        https://docs.aws.amazon.com/ses/latest/dg/notification-contents.html#complaint-object
-        """
-        assert self.user.profile.auto_block_spam is False
 
+@override_settings(STATSD_ENABLED=True)
+class ComplaintHandlingTest(TestCase):
+    """Test Complaint notifications and events."""
+
+    def setUp(self):
+        self.user = baker.make(User, email="[email protected]")
+        self.sa: SocialAccount = baker.make(
+            SocialAccount, user=self.user, provider="fxa", uid=str(uuid4())
+        )
         complaint = {
             "notificationType": "Complaint",
             "complaint": {
@@ -968,9 +1049,20 @@ def test_notification_type_complaint(self):
                 ),
             },
         }
-        json_body = {"Message": json.dumps(complaint)}
-        with MetricsMock() as mm:
-            response = _sns_notification(json_body)
+        self.complaint_body = {"Message": json.dumps(complaint)}
+
+    def test_notification_type_complaint(self):
+        """
+        A notificationType of complaint increments a counter, logs details, and
+        returns 200.
+
+        Example derived from:
+        https://docs.aws.amazon.com/ses/latest/dg/notification-contents.html#complaint-object
+        """
+        assert self.user.profile.auto_block_spam is False
+
+        with self.assertLogs(INFO_LOG) as logs, MetricsMock() as mm:
+            response = _sns_notification(self.complaint_body)
         assert response.status_code == 200
 
         self.user.profile.refresh_from_db()
@@ -985,20 +1077,30 @@ def test_notification_type_complaint(self):
                 "relay_action:auto_block_spam",
             ],
         )
-        assert len(self.caplog.records) == 2
-        record1, record2 = self.caplog.records
-        assert record1.msg == "complaint_notification"
-        assert record1.complaint_subtype is None
-        assert record1.complaint_user_agent == "ExampleCorp Feedback Loop (V0.01)"
-        assert record1.complaint_feedback == "abuse"
-        assert record1.user_match == "found"
-        assert record1.relay_action == "auto_block_spam"
-        assert record1.domain == "test.com"
-
-        assert record2.msg == "complaint_received"
-        assert record2.recipient_domains == ["test.com"]
-        assert record2.subtype is None
-        assert record2.feedback == "abuse"
+        assert len(logs.records) == 1
+        record = logs.records[0]
+        assert record.msg == "complaint_notification"
+        log_data = log_extra(record)
+        assert log_data == {
+            "complaint_feedback": "abuse",
+            "complaint_subtype": None,
+            "complaint_user_agent": "ExampleCorp Feedback Loop (V0.01)",
+            "domain": "test.com",
+            "relay_action": "auto_block_spam",
+            "user_match": "found",
+            "fxa_id": self.sa.uid,
+        }
+
+    def test_complaint_log_with_optout(self) -> None:
+        self.sa.extra_data["metricsEnabled"] = False
+        self.sa.save()
+
+        with self.assertLogs(INFO_LOG) as logs:
+            _sns_notification(self.complaint_body)
+
+        log_data = log_extra(logs.records[0])
+        assert log_data["user_match"] == "found"
+        assert not log_data["fxa_id"]
 
 
 class SNSNotificationRemoveEmailsInS3Test(TestCase):

emails/views.py

@@ -1439,9 +1439,7 @@ def _handle_bounce(message_json: AWS_SNSMessageJSON) -> HttpResponse:
     * bounce_diagnostic: 'diagnosticCode' from bounced recipient data, or None
     * bounce_extra: Extra data from bounce_recipient data, if any
     * domain: User's real email address domain, if an address was given
-
-    Emits a legacy log "bounced recipient domain: {domain}", with data from
-    bounced recipient data, without the email address.
+    * fxa_id - The Mozilla account (previously known as Firefox Account) ID of the user
     """
     bounce = message_json.get("bounce", {})
     bounce_type = bounce.get("bounceType", "none")
@@ -1476,6 +1474,10 @@ def _handle_bounce(message_json: AWS_SNSMessageJSON) -> HttpResponse:
             user = User.objects.get(email=recipient_address)
             profile = user.profile
             data["user_match"] = "found"
+            if (fxa := profile.fxa) and profile.metrics_enabled:
+                data["fxa_id"] = fxa.uid
+            else:
+                data["fxa_id"] = ""
         except User.DoesNotExist:
             # TODO: handle bounce for a user who no longer exists
             # add to SES account-wide suppression list?
@@ -1518,19 +1520,6 @@ def _handle_bounce(message_json: AWS_SNSMessageJSON) -> HttpResponse:
         )
         info_logger.info("bounce_notification", extra=data)
 
-        # Legacy log, can be removed Q4 2023
-        recipient_domain = data.get("domain")
-        if recipient_domain:
-            legacy_extra = {
-                "action": data.get("bounce_action"),
-                "status": data.get("bounce_status"),
-                "diagnosticCode": data.get("bounce_diagnostic"),
-            }
-            legacy_extra.update(data.get("bounce_extra", {}))
-            info_logger.info(
-                f"bounced recipient domain: {recipient_domain}", extra=legacy_extra
-            )
-
     if any(data["user_match"] == "missing" for data in bounce_data):
         return HttpResponse("Address does not exist", status=404)
     return HttpResponse("OK", status=200)
@@ -1557,11 +1546,7 @@ def _handle_complaint(message_json: AWS_SNSMessageJSON) -> HttpResponse:
     * complaint_user_agent - identifies the client used to file the complaint
     * complaint_extra - Extra data from complainedRecipients data, if any
     * domain - User's domain, if an address was given
-
-    Emits a legacy log "complaint_received", with data:
-    * recipient_domains: list of extracted user domains
-    * subtype: 'onaccounsuppressionlist', or 'none'
-    * feedback: feedback from ISP or 'none'
+    * fxa_id - The Mozilla account (previously known as Firefox Account) ID of the user
     """
     complaint = deepcopy(message_json.get("complaint", {}))
     complained_recipients = complaint.pop("complainedRecipients", [])
@@ -1594,6 +1579,10 @@ def _handle_complaint(message_json: AWS_SNSMessageJSON) -> HttpResponse:
             user = User.objects.get(email=recipient_address)
             profile = user.profile
             data["user_match"] = "found"
+            if (fxa := profile.fxa) and profile.metrics_enabled:
+                data["fxa_id"] = fxa.uid
+            else:
+                data["fxa_id"] = ""
         except User.DoesNotExist:
             data["user_match"] = "missing"
             continue
@@ -1620,17 +1609,6 @@ def _handle_complaint(message_json: AWS_SNSMessageJSON) -> HttpResponse:
         )
         info_logger.info("complaint_notification", extra=data)
 
-    # Legacy log, can be removed Q4 2023
-    domains = [data["domain"] for data in complaint_data if "domain" in data]
-    info_logger.info(
-        "complaint_received",
-        extra={
-            "recipient_domains": sorted(domains),
-            "subtype": subtype,
-            "feedback": feedback,
-        },
-    )
-
     if any(data["user_match"] == "missing" for data in complaint_data):
         return HttpResponse("Address does not exist", status=404)
     return HttpResponse("OK", status=200)