diff --git a/packages/fxa-auth-server/bin/email_notifications.js b/packages/fxa-auth-server/bin/email_notifications.js index a9eb8aab53d..e5e7d64e439 100644 --- a/packages/fxa-auth-server/bin/email_notifications.js +++ b/packages/fxa-auth-server/bin/email_notifications.js @@ -67,6 +67,7 @@ const Token = require('../lib/tokens')(log, config); const SQSReceiver = require('../lib/sqs')(log, statsd); const bounces = require('../lib/email/bounces')(log, error, config, statsd); const delivery = require('../lib/email/delivery')(log, glean); +const deliveryDelay = require('../lib/email/delivery-delay')(log, statsd); const notifications = require('../lib/email/notifications')(log, error); const { createDB } = require('../lib/db'); @@ -76,6 +77,7 @@ const { bounceQueueUrl, complaintQueueUrl, deliveryQueueUrl, + deliveryDelayQueueUrl, notificationQueueUrl, region, } = config.emailNotifications; @@ -85,10 +87,12 @@ const bounceQueue = new SQSReceiver(region, [ complaintQueueUrl, ]); const deliveryQueue = new SQSReceiver(region, [deliveryQueueUrl]); +const deliveryDelayQueue = new SQSReceiver(region, [deliveryDelayQueueUrl]); const notificationQueue = new SQSReceiver(region, [notificationQueueUrl]); DB.connect(config).then((db) => { bounces(bounceQueue, db); delivery(deliveryQueue); + deliveryDelay(deliveryDelayQueue); notifications(notificationQueue, db); }); diff --git a/packages/fxa-auth-server/config/index.ts b/packages/fxa-auth-server/config/index.ts index ed875828a13..f92ecd19578 100644 --- a/packages/fxa-auth-server/config/index.ts +++ b/packages/fxa-auth-server/config/index.ts @@ -751,6 +751,12 @@ const convictConf = convict({ env: 'DELIVERY_QUEUE_URL', default: '', }, + deliveryDelayQueueUrl: { + doc: 'The email delivery delay queue URL to use (should include https://sqs..amazonaws.com//)', + format: String, + env: 'DELIVERY_DELAY_QUEUE_URL', + default: '', + }, notificationQueueUrl: { doc: 'Queue URL for notifications from fxa-email-service (eventually this will be the only email-related queue)', format: String, diff --git a/packages/fxa-auth-server/lib/email/delivery-delay.ts b/packages/fxa-auth-server/lib/email/delivery-delay.ts new file mode 100644 index 00000000000..3c7d7dc34d9 --- /dev/null +++ b/packages/fxa-auth-server/lib/email/delivery-delay.ts @@ -0,0 +1,189 @@ +/* This Source Code Form is subject to the terms of the Mozilla Public + * License, v. 2.0. If a copy of the MPL was not distributed with this + * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ + +/** + * Handles AWS SES Delivery Delay notifications from SQS. + * + * Delivery delays are TRANSIENT failures where email delivery is temporarily delayed + * but may eventually succeed. This differs from bounces which are PERMANENT failures. + * Delays can occur due to mailbox full, temporary network issues, rate limiting, etc. + * + * Integration Requirements: + * - AWS SES must be configured to publish DeliveryDelay notifications to an SQS queue + * - Environment variable DELIVERY_DELAY_QUEUE_URL must point to the queue + * - SQS queue must have proper IAM permissions for the auth-server to consume messages + */ + +import { StatsD } from 'hot-shots'; +import { Logger } from 'mozlog'; +import { EventEmitter } from 'events'; +import * as utils from './utils/helpers'; + +interface SESMailHeader { + name: string; + value: string; +} + +interface SESMail { + timestamp: string; + messageId: string; + source: string; + headers?: SESMailHeader[]; +} + +interface DelayedRecipient { + emailAddress: string; + status?: string; + diagnosticCode?: string; +} + +/** + * AWS SES Delivery Delay types as documented in: + * https://docs.aws.amazon.com/ses/latest/dg/event-publishing-retrieving-sns-contents.html + */ +interface DeliveryDelay { + delayType: + | 'InternalFailure' + | 'General' + | 'MailboxFull' + | 'SpamDetected' + | 'RecipientServerError' + | 'IPFailure' + | 'TransientCommunicationFailure' + | 'BYOIPHostNameLookupUnavailable' + | 'Undetermined' + | 'SendingDeferral'; + delayedRecipients: DelayedRecipient[]; + expirationTime?: string; + reportingMTA?: string; + timestamp?: string; +} + +interface SESDeliveryDelayMessage { + eventType?: 'DeliveryDelay'; + notificationType?: 'DeliveryDelay'; + deliveryDelay: DeliveryDelay; + mail: SESMail; + del: () => void; +} + +interface SQSReceiver extends EventEmitter { + start: () => void; +} + +export = function (log: Logger, statsd: StatsD) { + return function start(deliveryDelayQueue: SQSReceiver) { + async function handleDeliveryDelay(message: SESDeliveryDelayMessage) { + try { + utils.logErrorIfHeadersAreWeirdOrMissing(log, message, 'deliveryDelay'); + + // Track message age to monitor how long delays persist + let messageAgeSeconds = 0; + if (message.mail?.timestamp) { + const mailTimestamp = new Date(message.mail.timestamp).getTime(); + const now = Date.now(); + messageAgeSeconds = Math.floor((now - mailTimestamp) / 1000); + statsd.timing('email.deliveryDelay.ageSeconds', messageAgeSeconds); + } + + statsd.increment('email.deliveryDelay.message', { + delayType: message?.deliveryDelay?.delayType || 'none', + hasExpiration: String(!!message?.deliveryDelay?.expirationTime), + template: utils.getHeaderValue('X-Template-Name', message) || 'none', + }); + + let recipients: DelayedRecipient[] = []; + if ( + message.deliveryDelay && + (message.eventType === 'DeliveryDelay' || + message.notificationType === 'DeliveryDelay') + ) { + recipients = message.deliveryDelay.delayedRecipients || []; + } + + const templateName = utils.getHeaderValue('X-Template-Name', message); + const language = utils.getHeaderValue('Content-Language', message); + const delayType = message.deliveryDelay?.delayType; + const expirationTime = message.deliveryDelay?.expirationTime; + const reportingMTA = message.deliveryDelay?.reportingMTA; + const timestamp = message.deliveryDelay?.timestamp; + + for (const recipient of recipients) { + const email = recipient.emailAddress; + const emailDomain = utils.getAnonymizedEmailDomain(email); + const logData: { + email: string; + domain: string; + delayType?: DeliveryDelay['delayType']; + status?: string; + diagnosticCode?: string; + template?: string; + lang?: string; + expirationTime?: string; + reportingMTA?: string; + timestamp?: string; + messageAgeSeconds?: number; + } = { + email: email, + domain: emailDomain, + delayType: delayType, + }; + + if (recipient.status) { + logData.status = recipient.status; + } + if (recipient.diagnosticCode) { + logData.diagnosticCode = recipient.diagnosticCode; + } + + if (templateName) { + logData.template = templateName; + } + + if (language) { + logData.lang = language; + } + + if (expirationTime) { + logData.expirationTime = expirationTime; + } + + if (reportingMTA) { + logData.reportingMTA = reportingMTA; + } + + if (timestamp) { + logData.timestamp = timestamp; + } + + if (messageAgeSeconds > 0) { + logData.messageAgeSeconds = messageAgeSeconds; + } + + utils.logAccountEventFromMessage(message, 'emailDelayed'); + + log.info('handleDeliveryDelay', logData); + } + + message.del(); + } catch (err) { + // Log error but still delete message to prevent infinite retry loop + log.error('handleDeliveryDelay.error', { + err: err, + messageId: message?.mail?.messageId, + }); + statsd.increment('email.deliveryDelay.error'); + message.del(); + } + } + + deliveryDelayQueue.on('data', handleDeliveryDelay); + deliveryDelayQueue.start(); + + return { + deliveryDelayQueue: deliveryDelayQueue, + handleDeliveryDelay: handleDeliveryDelay, + }; + }; +}; diff --git a/packages/fxa-auth-server/lib/email/utils/helpers.js b/packages/fxa-auth-server/lib/email/utils/helpers.js index 07977073ba2..3352d8ba4f2 100644 --- a/packages/fxa-auth-server/lib/email/utils/helpers.js +++ b/packages/fxa-auth-server/lib/email/utils/helpers.js @@ -207,6 +207,10 @@ function logEmailEventFromMessage(log, message, type, emailDomain) { emailEventInfo.complaint = true; } + if (message.deliveryDelay) { + emailEventInfo.delayed = true; + } + log.info('emailEvent', emailEventInfo); logAmplitudeEvent(log, message, emailEventInfo); diff --git a/packages/fxa-auth-server/test/local/email/delivery-delay.js b/packages/fxa-auth-server/test/local/email/delivery-delay.js new file mode 100644 index 00000000000..2ff461c8e6a --- /dev/null +++ b/packages/fxa-auth-server/test/local/email/delivery-delay.js @@ -0,0 +1,210 @@ +/* This Source Code Form is subject to the terms of the Mozilla Public + * License, v. 2.0. If a copy of the MPL was not distributed with this + * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ + +'use strict'; + +const { assert } = require('chai'); +const EventEmitter = require('events').EventEmitter; +const { mockLog, mockStatsd } = require('../../mocks'); +const sinon = require('sinon'); +const emailHelpers = require('../../../lib/email/utils/helpers'); +const deliveryDelay = require('../../../lib/email/delivery-delay'); + +let sandbox; +const mockDeliveryDelayQueue = new EventEmitter(); +mockDeliveryDelayQueue.start = function start() {}; + +function mockMessage(msg) { + msg.del = sandbox.spy(); + msg.headers = msg.headers || {}; + return msg; +} + +function createDeliveryDelayMessage(overrides = {}) { + const defaults = { + eventType: 'DeliveryDelay', + deliveryDelay: { + delayType: 'TransientCommunicationFailure', + delayedRecipients: [{ emailAddress: 'user@example.com' }], + }, + mail: { + timestamp: '2023-12-17T14:59:38.237Z', + messageId: 'test-message-id', + source: 'sender@example.com', + headers: [], + }, + }; + return mockMessage({ ...defaults, ...overrides }); +} + +function mockedDeliveryDelay(log, statsd) { + return deliveryDelay(log, statsd)(mockDeliveryDelayQueue); +} + +describe('delivery delay messages', () => { + beforeEach(() => { + sandbox = sinon.createSandbox(); + }); + + afterEach(() => { + sandbox.restore(); + }); + + it('should not log an error for headers', async () => { + const log = mockLog(); + const statsd = mockStatsd(); + await mockedDeliveryDelay(log, statsd).handleDeliveryDelay( + mockMessage({ junk: 'message' }) + ); + assert.equal(log.error.callCount, 0); + }); + + it('should log an error for missing headers', async () => { + const log = mockLog(); + const statsd = mockStatsd(); + const message = mockMessage({ junk: 'message' }); + message.headers = undefined; + await mockedDeliveryDelay(log, statsd).handleDeliveryDelay(message); + assert.equal(log.error.callCount, 1); + }); + + it('should log delivery delay with all fields', async () => { + const log = mockLog(); + const statsd = mockStatsd(); + const mockMsg = createDeliveryDelayMessage({ + deliveryDelay: { + delayType: 'TransientCommunicationFailure', + timestamp: '2023-12-17T14:59:38.237Z', + delayedRecipients: [ + { + emailAddress: 'recipient@example.com', + status: '4.4.7', + diagnosticCode: 'smtp; 450 4.4.7 Message delayed', + }, + ], + expirationTime: '2023-12-18T14:59:38.237Z', + reportingMTA: 'a1-23.smtp-out.amazonses.com', + }, + mail: { + headers: [ + { name: 'X-Template-Name', value: 'verifyLoginEmail' }, + { name: 'Content-Language', value: 'en' }, + ], + }, + }); + + await mockedDeliveryDelay(log, statsd).handleDeliveryDelay(mockMsg); + + sinon.assert.calledOnceWithExactly( + statsd.increment, + 'email.deliveryDelay.message', + { + delayType: 'TransientCommunicationFailure', + hasExpiration: 'true', + template: 'verifyLoginEmail', + } + ); + + const loggedData = log.info.args[0][1]; + assert.equal(log.info.args[0][0], 'handleDeliveryDelay'); + assert.include(loggedData, { + email: 'recipient@example.com', + domain: 'other', + delayType: 'TransientCommunicationFailure', + status: '4.4.7', + template: 'verifyLoginEmail', + lang: 'en', + expirationTime: '2023-12-18T14:59:38.237Z', + reportingMTA: 'a1-23.smtp-out.amazonses.com', + }); + }); + + it('should handle delivery delay with notificationType', async () => { + const log = mockLog(); + const statsd = mockStatsd(); + const mockMsg = createDeliveryDelayMessage({ + notificationType: 'DeliveryDelay', + eventType: undefined, + deliveryDelay: { + delayType: 'MailboxFull', + delayedRecipients: [{ emailAddress: 'user@example.com', status: '4.2.2' }], + }, + }); + + await mockedDeliveryDelay(log, statsd).handleDeliveryDelay(mockMsg); + + assert.equal(statsd.increment.args[0][1].delayType, 'MailboxFull'); + assert.include(log.info.args[0][1], { + email: 'user@example.com', + status: '4.2.2', + }); + }); + + it('should log account email event (emailDelayed)', async () => { + sandbox.stub(emailHelpers, 'logAccountEventFromMessage').returns(Promise.resolve()); + const log = mockLog(); + const statsd = mockStatsd(); + const mockMsg = createDeliveryDelayMessage({ + deliveryDelay: { + delayType: 'SpamDetected', + delayedRecipients: [{ emailAddress: 'user@example.com' }], + }, + mail: { headers: [{ name: 'X-Uid', value: 'test-uid-123' }] }, + }); + + await mockedDeliveryDelay(log, statsd).handleDeliveryDelay(mockMsg); + sinon.assert.calledOnceWithExactly( + emailHelpers.logAccountEventFromMessage, + mockMsg, + 'emailDelayed' + ); + }); + + it('should handle popular email domain', async () => { + const log = mockLog(); + const statsd = mockStatsd(); + const mockMsg = createDeliveryDelayMessage({ + deliveryDelay: { + delayType: 'RecipientServerError', + delayedRecipients: [{ emailAddress: 'user@yahoo.com' }], + }, + }); + + await mockedDeliveryDelay(log, statsd).handleDeliveryDelay(mockMsg); + + assert.equal(log.info.args[0][1].domain, 'yahoo.com'); + }); + + it('should handle missing delayedRecipients gracefully', async () => { + const log = mockLog(); + const statsd = mockStatsd(); + const mockMsg = createDeliveryDelayMessage({ + deliveryDelay: { delayType: 'Undetermined', delayedRecipients: undefined }, + }); + + await mockedDeliveryDelay(log, statsd).handleDeliveryDelay(mockMsg); + + sinon.assert.calledOnce(statsd.increment); + assert.equal(log.info.callCount, 0); + sinon.assert.calledOnce(mockMsg.del); + }); + + it('should handle errors and still delete message', async () => { + const log = mockLog(); + const statsd = mockStatsd(); + const mockMsg = createDeliveryDelayMessage(); + + sandbox.stub(emailHelpers, 'getAnonymizedEmailDomain').throws(new Error('Test error')); + + await mockedDeliveryDelay(log, statsd).handleDeliveryDelay(mockMsg); + + sinon.assert.calledWith(log.error, 'handleDeliveryDelay.error'); + assert.include(log.error.args[0][1], { + messageId: 'test-message-id', + }); + + sinon.assert.calledWith(statsd.increment, 'email.deliveryDelay.error'); + sinon.assert.calledOnce(mockMsg.del); + }); +});