diff --git a/emails/tests/views_tests.py b/emails/tests/views_tests.py index a1ccfad46b..7175029939 100644 --- a/emails/tests/views_tests.py +++ b/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="relayuser@test.com") + 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="relayuser@test.com") + 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="relayuser@test.com") + 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): diff --git a/emails/views.py b/emails/views.py index 175a1233c2..0ca8a5172f 100644 --- a/emails/views.py +++ b/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)