🐛 Fixed storing email failures with an empty message (#16260)

no issue

- When we receive an email failure with an empty message, the saving of
the model would fail because of schema validation that requires strings
to be non-empty.
- This adds more logging to the email analytics service to help debug
future issues
- Performance improvement to storing delivered, opened and failed emails
by replacing COALESCE with WHERE X IS NULL (tested and should give a
decent performance boost locally).

ghost/core/core/server/services/email-analytics/wrapper.js

@@ -55,6 +55,24 @@ class EmailAnalyticsServiceWrapper {
         });
     }
 
+    async fetchLatest() {
+        const fetchStartDate = new Date();
+        debug('Starting email analytics fetch of latest events');
+        const eventStats = await this.service.fetchLatest();
+        const fetchEndDate = new Date();
+        debug(`Finished fetching ${eventStats.totalEvents} analytics events in ${fetchEndDate.getTime() - fetchStartDate.getTime()}ms`);
+
+        const aggregateStartDate = new Date();
+        debug(`Starting email analytics aggregation for ${eventStats.emailIds.length} emails`);
+        await this.service.aggregateStats(eventStats);
+        const aggregateEndDate = new Date();
+        debug(`Finished aggregating email analytics in ${aggregateEndDate.getTime() - aggregateStartDate.getTime()}ms`);
+
+        logging.info(`Fetched ${eventStats.totalEvents} events and aggregated stats for ${eventStats.emailIds.length} emails in ${aggregateEndDate.getTime() - fetchStartDate.getTime()}ms`);
+
+        return eventStats;
+    }
+
     async startFetch() {
         if (this.fetching) {
             logging.info('Email analytics fetch already running, skipping');
@@ -64,24 +82,15 @@ class EmailAnalyticsServiceWrapper {
 
         logging.info('Email analytics fetch started');
         try {
-            const fetchStartDate = new Date();
-            debug('Starting email analytics fetch of latest events');
-            const eventStats = await this.service.fetchLatest();
-            const fetchEndDate = new Date();
-            debug(`Finished fetching ${eventStats.totalEvents} analytics events in ${fetchEndDate.getTime() - fetchStartDate.getTime()}ms`);
-
-            const aggregateStartDate = new Date();
-            debug(`Starting email analytics aggregation for ${eventStats.emailIds.length} emails`);
-            await this.service.aggregateStats(eventStats);
-            const aggregateEndDate = new Date();
-            debug(`Finished aggregating email analytics in ${aggregateEndDate.getTime() - aggregateStartDate.getTime()}ms`);
-
-            logging.info(`Fetched ${eventStats.totalEvents} events and aggregated stats for ${eventStats.emailIds.length} emails in ${aggregateEndDate.getTime() - fetchStartDate.getTime()}ms`);
+            const eventStats = await this.fetchLatest();
 
             this.fetching = false;
             return eventStats;
         } catch (e) {
             logging.error(e, 'Error while fetching email analytics');
+
+            // Log again only the error, otherwise we lose the stack trace
+            logging.error(e);
         }
         this.fetching = false;
     }

ghost/core/test/integration/services/email-service/email-event-storage.test.js

@@ -77,7 +77,7 @@ describe('EmailEventStorage', function () {
 
         // Fire event processing
         // We use offloading to have correct coverage and usage of worker thread
-        const result = await emailAnalytics.startFetch();
+        const result = await emailAnalytics.fetchLatest();
         assert.equal(result.delivered, 1);
         assert.deepEqual(result.emailIds, [emailId]);
         assert.deepEqual(result.memberIds, [memberId]);
@@ -128,7 +128,7 @@ describe('EmailEventStorage', function () {
         assert.equal(initialModel.get('delivered_at'), null);
 
         // Fire event processing
-        const result = await emailAnalytics.startFetch();
+        const result = await emailAnalytics.fetchLatest();
         assert.equal(result.delivered, 1);
         assert.deepEqual(result.emailIds, [emailId]);
         assert.deepEqual(result.memberIds, [memberId]);
@@ -176,7 +176,7 @@ describe('EmailEventStorage', function () {
         assert.equal(initialModel.get('opened_at'), null);
 
         // Fire event processing
-        const result = await emailAnalytics.startFetch();
+        const result = await emailAnalytics.fetchLatest();
         assert.equal(result.opened, 1);
         assert.deepEqual(result.emailIds, [emailId]);
         assert.deepEqual(result.memberIds, [memberId]);
@@ -258,7 +258,7 @@ describe('EmailEventStorage', function () {
         assert.notEqual(initialModel.get('delivered_at'), null);
 
         // Fire event processing
-        const result = await emailAnalytics.startFetch();
+        const result = await emailAnalytics.fetchLatest();
         assert.equal(result.permanentFailed, 1);
         assert.deepEqual(result.emailIds, [emailId]);
         assert.deepEqual(result.memberIds, [memberId]);
@@ -292,6 +292,104 @@ describe('EmailEventStorage', function () {
         assert.equal(permanentFailures.models[0].get('failed_at').toUTCString(), timestamp.toUTCString());
     });
 
+    it('Can handle permanent failure events without message and description', async function () {
+        const emailBatch = fixtureManager.get('email_batches', 0);
+        const emailId = emailBatch.email_id;
+
+        const emailRecipient = fixtureManager.get('email_recipients', 4);
+        assert(emailRecipient.batch_id === emailBatch.id);
+        const memberId = emailRecipient.member_id;
+        const providerId = emailBatch.provider_id;
+        const timestamp = new Date(2000, 0, 1);
+
+        events = [{
+            event: 'failed',
+            id: 'pl271FzxTTmGRW8Uj3dUWw',
+            'log-level': 'error',
+            severity: 'permanent',
+            reason: 'suppress-bounce',
+            envelope: {
+                sender: 'john@example.org',
+                transport: 'smtp',
+                targets: 'joan@example.com'
+            },
+            flags: {
+                'is-routed': false,
+                'is-authenticated': true,
+                'is-system-test': false,
+                'is-test-mode': false
+            },
+            'delivery-status': {
+                'attempt-no': 1,
+                message: '',
+                code: 605,
+                description: '',
+                'session-seconds': 0.0
+            },
+            message: {
+                headers: {
+                    to: 'joan@example.com',
+                    'message-id': providerId,
+                    from: 'john@example.org',
+                    subject: 'Test Subject'
+                },
+                attachments: [],
+                size: 867
+            },
+            storage: {
+                url: 'https://se.api.mailgun.net/v3/domains/example.org/messages/eyJwI...',
+                key: 'eyJwI...'
+            },
+            recipient: emailRecipient.member_email,
+            'recipient-domain': 'mailgun.com',
+            campaigns: [],
+            tags: [],
+            'user-variables': {},
+            timestamp: Math.round(timestamp.getTime() / 1000)
+        }];
+
+        const initialModel = await models.EmailRecipient.findOne({
+            id: emailRecipient.id
+        }, {require: true});
+
+        assert.equal(initialModel.get('failed_at'), null);
+        assert.notEqual(initialModel.get('delivered_at'), null);
+
+        // Fire event processing
+        const result = await emailAnalytics.fetchLatest();
+        assert.equal(result.permanentFailed, 1);
+        assert.deepEqual(result.emailIds, [emailId]);
+        assert.deepEqual(result.memberIds, [memberId]);
+
+        // Since this is all event based we should wait for all dispatched events to be completed.
+        await DomainEvents.allSettled();
+
+        // Check if status has changed to delivered, with correct timestamp
+        const updatedEmailRecipient = await models.EmailRecipient.findOne({
+            id: emailRecipient.id
+        }, {require: true});
+
+        assert.equal(updatedEmailRecipient.get('failed_at').toUTCString(), timestamp.toUTCString());
+
+        // Check delivered at is NOT reset back to null
+        assert.notEqual(updatedEmailRecipient.get('delivered_at'), null);
+
+        // Check we have a stored permanent failure
+        const permanentFailures = await models.EmailRecipientFailure.findAll({
+            filter: `email_recipient_id:${emailRecipient.id}`
+        });
+        assert.equal(permanentFailures.length, 1);
+
+        assert.equal(permanentFailures.models[0].get('message'), 'Error 605');
+        assert.equal(permanentFailures.models[0].get('code'), 605);
+        assert.equal(permanentFailures.models[0].get('enhanced_code'), null);
+        assert.equal(permanentFailures.models[0].get('email_id'), emailId);
+        assert.equal(permanentFailures.models[0].get('member_id'), memberId);
+        assert.equal(permanentFailures.models[0].get('event_id'), 'pl271FzxTTmGRW8Uj3dUWw');
+        assert.equal(permanentFailures.models[0].get('severity'), 'permanent');
+        assert.equal(permanentFailures.models[0].get('failed_at').toUTCString(), timestamp.toUTCString());
+    });
+
     it('Ignores permanent failures if already failed', async function () {
         const emailBatch = fixtureManager.get('email_batches', 0);
         const emailId = emailBatch.email_id;
@@ -355,7 +453,7 @@ describe('EmailEventStorage', function () {
         assert.notEqual(initialModel.get('failed_at'), null, 'This test requires a failed email recipient');
 
         // Fire event processing
-        const result = await emailAnalytics.startFetch();
+        const result = await emailAnalytics.fetchLatest();
         assert.equal(result.permanentFailed, 1);
         assert.deepEqual(result.emailIds, [emailId]);
         assert.deepEqual(result.memberIds, [memberId]);
@@ -447,7 +545,7 @@ describe('EmailEventStorage', function () {
         assert.equal(initialModel.get('failed_at'), null);
 
         // Fire event processing
-        const result = await emailAnalytics.startFetch();
+        const result = await emailAnalytics.fetchLatest();
         assert.equal(result.permanentFailed, 1);
         assert.deepEqual(result.emailIds, [emailId]);
         assert.deepEqual(result.memberIds, [memberId]);
@@ -565,7 +663,7 @@ describe('EmailEventStorage', function () {
         assert.equal(initialModel.get('failed_at'), null);
 
         // Fire event processing
-        const result = await emailAnalytics.startFetch();
+        const result = await emailAnalytics.fetchLatest();
         assert.equal(result.temporaryFailed, 1);
         assert.deepEqual(result.emailIds, [emailId]);
         assert.deepEqual(result.memberIds, [memberId]);
@@ -669,7 +767,7 @@ describe('EmailEventStorage', function () {
         }];
 
         // Fire event processing
-        const result = await emailAnalytics.startFetch();
+        const result = await emailAnalytics.fetchLatest();
         assert.equal(result.temporaryFailed, 1);
         assert.deepEqual(result.emailIds, [emailId]);
         assert.deepEqual(result.memberIds, [memberId]);
@@ -701,6 +799,110 @@ describe('EmailEventStorage', function () {
         assert.equal(failures.models[0].get('failed_at').toUTCString(), timestamp.toUTCString());
     });
 
+    it('Correctly overwrites temporary failure event with other temporary one without message', async function () {
+        const emailBatch = fixtureManager.get('email_batches', 0);
+        const emailId = emailBatch.email_id;
+
+        const emailRecipient = fixtureManager.get('email_recipients', 0);
+        assert(emailRecipient.batch_id === emailBatch.id);
+        const memberId = emailRecipient.member_id;
+        const providerId = emailBatch.provider_id;
+        const timestamp = new Date(2001, 0, 2);
+
+        events = [{
+            event: 'failed',
+            severity: 'temporary',
+            recipient: emailRecipient.member_email,
+            'user-variables': {
+                'email-id': emailId
+            },
+            // unix timestamp
+            timestamp: Math.round(timestamp.getTime() / 1000),
+            tags: [],
+            storage: {
+                url: 'https://storage-us-east4.api.mailgun.net/v3/domains/...',
+                region: 'us-east4',
+                key: 'AwABB...',
+                env: 'production'
+            },
+            'delivery-status': {
+                tls: true,
+                code: 555,
+                description: '',
+                utf8: true,
+                'retry-seconds': 600,
+                'attempt-no': 1,
+                message: '',
+                'certificate-verified': true
+            },
+            batch: {
+                id: '633ee6154618b2fed628ccb0'
+            },
+            'recipient-domain': 'test.com',
+            id: 'updated_event_id',
+            campaigns: [],
+            reason: 'generic',
+            flags: {
+                'is-routed': false,
+                'is-authenticated': true,
+                'is-system-test': false,
+                'is-test-mode': false
+            },
+            'log-level': 'warn',
+            template: {
+                name: 'test'
+            },
+            envelope: {
+                transport: 'smtp',
+                sender: 'test@test.com',
+                'sending-ip': 'xxx.xxx.xxx.xxx',
+                targets: 'test@test.com'
+            },
+            message: {
+                headers: {
+                    to: 'test@test.net',
+                    'message-id': providerId,
+                    from: 'test@test.com',
+                    subject: 'Test send'
+                },
+                attachments: [],
+                size: 3499
+            }
+        }];
+
+        // Fire event processing
+        const result = await emailAnalytics.fetchLatest();
+        assert.equal(result.temporaryFailed, 1);
+        assert.deepEqual(result.emailIds, [emailId]);
+        assert.deepEqual(result.memberIds, [memberId]);
+
+        // Since this is all event based we should wait for all dispatched events to be completed.
+        await DomainEvents.allSettled();
+
+        // Check if status has changed to delivered, with correct timestamp
+        const updatedEmailRecipient = await models.EmailRecipient.findOne({
+            id: emailRecipient.id
+        }, {require: true});
+
+        // Not mark as failed
+        assert.equal(updatedEmailRecipient.get('failed_at'), null);
+
+        // Check we have a stored temporary failure
+        const failures = await models.EmailRecipientFailure.findAll({
+            filter: `email_recipient_id:${emailRecipient.id}`
+        });
+        assert.equal(failures.length, 1);
+
+        assert.equal(failures.models[0].get('email_id'), emailId);
+        assert.equal(failures.models[0].get('member_id'), memberId);
+        assert.equal(failures.models[0].get('severity'), 'temporary');
+        assert.equal(failures.models[0].get('event_id'), 'updated_event_id');
+        assert.equal(failures.models[0].get('message'), 'Error 555');
+        assert.equal(failures.models[0].get('code'), 555);
+        assert.equal(failures.models[0].get('enhanced_code'), null); // should be set to null instead of kept
+        assert.equal(failures.models[0].get('failed_at').toUTCString(), timestamp.toUTCString());
+    });
+
     it('Correctly overwrites permanent failure event with other permanent one', async function () {
         const emailBatch = fixtureManager.get('email_batches', 0);
         const emailId = emailBatch.email_id;
@@ -709,7 +911,7 @@ describe('EmailEventStorage', function () {
         assert(emailRecipient.batch_id === emailBatch.id);
         const memberId = emailRecipient.member_id;
         const providerId = emailBatch.provider_id;
-        const timestamp = new Date(2001, 0, 1);
+        const timestamp = new Date(2001, 0, 3);
 
         events = [{
             event: 'failed',
@@ -773,7 +975,7 @@ describe('EmailEventStorage', function () {
         }];
 
         // Fire event processing
-        const result = await emailAnalytics.startFetch();
+        const result = await emailAnalytics.fetchLatest();
         assert.equal(result.permanentFailed, 1);
         assert.deepEqual(result.emailIds, [emailId]);
         assert.deepEqual(result.memberIds, [memberId]);
@@ -839,7 +1041,7 @@ describe('EmailEventStorage', function () {
         }];
 
         // Fire event processing
-        const result = await emailAnalytics.startFetch();
+        const result = await emailAnalytics.fetchLatest();
         assert.equal(result.complained, 1);
         assert.deepEqual(result.emailIds, [emailId]);
         assert.deepEqual(result.memberIds, [memberId]);
@@ -890,7 +1092,7 @@ describe('EmailEventStorage', function () {
         }];
 
         // Fire event processing
-        const result = await emailAnalytics.startFetch();
+        const result = await emailAnalytics.fetchLatest();
         assert.equal(result.unsubscribed, 1);
         assert.deepEqual(result.emailIds, [emailId]);
         assert.deepEqual(result.memberIds, [memberId]);
@@ -929,7 +1131,7 @@ describe('EmailEventStorage', function () {
         }];
 
         // Fire event processing
-        const result = await emailAnalytics.startFetch();
+        const result = await emailAnalytics.fetchLatest();
         assert.equal(result.unhandled, 1);
         assert.deepEqual(result.emailIds, []);
         assert.deepEqual(result.memberIds, []);
@@ -945,7 +1147,7 @@ describe('EmailEventStorage', function () {
         }];
 
         // Fire event processing
-        const result = await emailAnalytics.startFetch();
+        const result = await emailAnalytics.fetchLatest();
         assert.equal(result.unhandled, 0);
         assert.deepEqual(result.emailIds, []);
         assert.deepEqual(result.memberIds, []);

ghost/email-analytics-service/lib/email-analytics-service.js

@@ -1,5 +1,6 @@
 const EventProcessingResult = require('./event-processing-result');
 const debug = require('@tryghost/debug')('services:email-analytics');
+const logging = require('@tryghost/logging');
 
 /**
  * @typedef {import('@tryghost/email-service').EmailEventProcessor} EmailEventProcessor
@@ -176,9 +177,12 @@ module.exports = class EmailAnalyticsService {
     }
 
     async aggregateStats({emailIds = [], memberIds = []}) {
+        logging.info(`Aggregating email analytics for ${emailIds.length} emails`);
         for (const emailId of emailIds) {
             await this.aggregateEmailStats(emailId);
         }
+
+        logging.info(`Aggregating email analytics for ${memberIds.length} members`);
         for (const memberId of memberIds) {
             await this.aggregateMemberStats(memberId);
         }

ghost/email-service/lib/email-event-storage.js

@@ -17,8 +17,9 @@ class EmailEventStorage {
         // only set if delivered_at is null
         await this.#db.knex('email_recipients')
             .where('id', '=', event.emailRecipientId)
+            .whereNull('delivered_at')
             .update({
-                delivered_at: this.#db.knex.raw('COALESCE(delivered_at, ?)', [moment.utc(event.timestamp).format('YYYY-MM-DD HH:mm:ss')])
+                delivered_at: moment.utc(event.timestamp).format('YYYY-MM-DD HH:mm:ss')
             });
     }
 
@@ -27,8 +28,9 @@ class EmailEventStorage {
         // only set if opened_at is null
         await this.#db.knex('email_recipients')
             .where('id', '=', event.emailRecipientId)
+            .whereNull('opened_at')
             .update({
-                opened_at: this.#db.knex.raw('COALESCE(opened_at, ?)', [moment.utc(event.timestamp).format('YYYY-MM-DD HH:mm:ss')])
+                opened_at: moment.utc(event.timestamp).format('YYYY-MM-DD HH:mm:ss')
             });
     }
 
@@ -37,8 +39,9 @@ class EmailEventStorage {
         // only set if failed_at is null
         await this.#db.knex('email_recipients')
             .where('id', '=', event.emailRecipientId)
+            .whereNull('failed_at')
             .update({
-                failed_at: this.#db.knex.raw('COALESCE(failed_at, ?)', [moment.utc(event.timestamp).format('YYYY-MM-DD HH:mm:ss')])
+                failed_at: moment.utc(event.timestamp).format('YYYY-MM-DD HH:mm:ss')
             });
         await this.saveFailure('permanent', event);
     }
@@ -78,7 +81,7 @@ class EmailEventStorage {
                 member_id: event.memberId,
                 email_recipient_id: event.emailRecipientId,
                 severity,
-                message: event.error.message,
+                message: event.error.message || `Error ${event.error.enhancedCode ?? event.error.code}`,
                 code: event.error.code,
                 enhanced_code: event.error.enhancedCode,
                 failed_at: event.timestamp,
@@ -98,7 +101,7 @@ class EmailEventStorage {
             // Update the existing failure
             await existing.save({
                 severity,
-                message: event.error.message,
+                message: event.error.message || `Error ${event.error.enhancedCode ?? event.error.code}`,
                 code: event.error.code,
                 enhanced_code: event.error.enhancedCode ?? null,
                 failed_at: event.timestamp,

ghost/email-service/test/email-event-storage.test.js

@@ -101,6 +101,97 @@ describe('Email Event Storage', function () {
         assert(existing.save.calledOnce);
     });
 
+    it('Handles email permanent bounce events with update and empty message', async function () {
+        const event = EmailBouncedEvent.create({
+            email: 'example@example.com',
+            memberId: '123',
+            emailId: '456',
+            emailRecipientId: '789',
+            error: {
+                message: '',
+                code: 500,
+                enhancedCode: '5.5.5'
+            },
+            timestamp: new Date(0)
+        });
+
+        const db = createDb();
+        const existing = {
+            id: 1,
+            get: (key) => {
+                if (key === 'severity') {
+                    return 'temporary';
+                }
+                if (key === 'failed_at') {
+                    return new Date(-5);
+                }
+            },
+            save: sinon.stub().resolves()
+        };
+        const EmailRecipientFailure = {
+            transaction: async function (callback) {
+                return await callback(1);
+            },
+            findOne: sinon.stub().resolves(existing)
+        };
+
+        const eventHandler = new EmailEventStorage({
+            db,
+            models: {
+                EmailRecipientFailure
+            }
+        });
+        await eventHandler.handlePermanentFailed(event);
+        sinon.assert.calledOnce(db.update);
+        assert(!!db.update.firstCall.args[0].failed_at);
+        assert(existing.save.calledOnce);
+    });
+
+    it('Handles email permanent bounce events with update and empty message and without enhanced code', async function () {
+        const event = EmailBouncedEvent.create({
+            email: 'example@example.com',
+            memberId: '123',
+            emailId: '456',
+            emailRecipientId: '789',
+            error: {
+                message: '',
+                code: 500
+            },
+            timestamp: new Date(0)
+        });
+
+        const db = createDb();
+        const existing = {
+            id: 1,
+            get: (key) => {
+                if (key === 'severity') {
+                    return 'temporary';
+                }
+                if (key === 'failed_at') {
+                    return new Date(-5);
+                }
+            },
+            save: sinon.stub().resolves()
+        };
+        const EmailRecipientFailure = {
+            transaction: async function (callback) {
+                return await callback(1);
+            },
+            findOne: sinon.stub().resolves(existing)
+        };
+
+        const eventHandler = new EmailEventStorage({
+            db,
+            models: {
+                EmailRecipientFailure
+            }
+        });
+        await eventHandler.handlePermanentFailed(event);
+        sinon.assert.calledOnce(db.update);
+        assert(!!db.update.firstCall.args[0].failed_at);
+        assert(existing.save.calledOnce);
+    });
+
     it('Handles email permanent bounce events with insert', async function () {
         const event = EmailBouncedEvent.create({
             email: 'example@example.com',
@@ -136,6 +227,75 @@ describe('Email Event Storage', function () {
         assert(EmailRecipientFailure.add.calledOnce);
     });
 
+    it('Handles email permanent bounce events with insert and empty message', async function () {
+        const event = EmailBouncedEvent.create({
+            email: 'example@example.com',
+            memberId: '123',
+            emailId: '456',
+            emailRecipientId: '789',
+            error: {
+                message: '',
+                code: 500,
+                enhancedCode: '5.5.5'
+            },
+            timestamp: new Date(0)
+        });
+
+        const db = createDb();
+        const EmailRecipientFailure = {
+            transaction: async function (callback) {
+                return await callback(1);
+            },
+            findOne: sinon.stub().resolves(undefined),
+            add: sinon.stub().resolves()
+        };
+
+        const eventHandler = new EmailEventStorage({
+            db,
+            models: {
+                EmailRecipientFailure
+            }
+        });
+        await eventHandler.handlePermanentFailed(event);
+        sinon.assert.calledOnce(db.update);
+        assert(!!db.update.firstCall.args[0].failed_at);
+        assert(EmailRecipientFailure.add.calledOnce);
+    });
+
+    it('Handles email permanent bounce events with insert and empty message and without enhanced code', async function () {
+        const event = EmailBouncedEvent.create({
+            email: 'example@example.com',
+            memberId: '123',
+            emailId: '456',
+            emailRecipientId: '789',
+            error: {
+                message: '',
+                code: 500
+            },
+            timestamp: new Date(0)
+        });
+
+        const db = createDb();
+        const EmailRecipientFailure = {
+            transaction: async function (callback) {
+                return await callback(1);
+            },
+            findOne: sinon.stub().resolves(undefined),
+            add: sinon.stub().resolves()
+        };
+
+        const eventHandler = new EmailEventStorage({
+            db,
+            models: {
+                EmailRecipientFailure
+            }
+        });
+        await eventHandler.handlePermanentFailed(event);
+        sinon.assert.calledOnce(db.update);
+        assert(!!db.update.firstCall.args[0].failed_at);
+        assert(EmailRecipientFailure.add.calledOnce);
+    });
+
     it('Handles email permanent bounce event without error data', async function () {
         const event = EmailBouncedEvent.create({
             email: 'example@example.com',