Fixed race condition when updating member's last_seen_at timestamp (#20389)

ref
https://linear.app/tryghost/issue/ENG-1240/race-condition-when-updating-members-last-seen-at-timestamp
    
When members click a link in an email, Ghost updates the member's
`last_seen_at` timestamp, but it should only update the timestamp if the
member hasn't yet been seen in the current day (based on the
publication's timezone).
    
Currently there is a race condition present where multiple simultaneous
requests from the same member (if e.g. an email link checker is
following all links in an email) can cause the `last_seen_at` timestamp
to be updated multiple times in the same day for the same member. These
additional queries add a significant load on Ghost and its database,
which can contribute to the exhaustion of the connection pool and
eventually requests may time out.
    
The primary motivation for this change is to avoid that race condition
by adding a lock to the member row, checking if `last_seen_at` has
already been updated in the current day, and only updating it if it
hasn't.
    
Another beneficial side-effect of this change is that it avoids locking
the `labels` and `newsletters` tables, which are locked when we update
the `last_seen_at` timestamp in the `members` table currently. This
should improve Ghost's ability to handle a large influx of requests to
redirect endpoints (confirmed with load tests), which tend to happen
immediately after a publisher sends an email.

ghost/core/core/server/services/members-events/index.js

@@ -1,5 +1,6 @@
 const labsService = require('../../../shared/labs');
 const DomainEvents = require('@tryghost/domain-events');
+const events = require('../../lib/common/events');
 const settingsCache = require('../../../shared/settings-cache');
 const members = require('../members');
 
@@ -32,7 +33,8 @@ class MembersEventsServiceWrapper {
             getMembersApi() {
                 return members.api;
             },
-            db
+            db,
+            events
         });
 
         this.eventStorage.subscribe(DomainEvents);

ghost/core/test/e2e-server/__snapshots__/click-tracking.test.js.snap

@@ -0,0 +1,43 @@
+// Jest Snapshot v1, https://goo.gl/fbAQLP
+
+exports[`Click Tracking Full test 1: [headers] 1`] = `
+Object {
+  "accept-encoding": "gzip, deflate, br",
+  "content-length": Any<Number>,
+  "content-type": "application/json",
+  "content-version": StringMatching /v\\\\d\\+\\\\\\.\\\\d\\+/,
+  "user-agent": StringMatching /Ghost\\\\/\\\\d\\+\\\\\\.\\\\d\\+\\\\\\.\\\\d\\+\\\\s\\\\\\(https:\\\\/\\\\/github\\.com\\\\/TryGhost\\\\/Ghost\\\\\\)/,
+}
+`;
+
+exports[`Click Tracking Full test 2: [body] 1`] = `
+Object {
+  "member": Object {
+    "current": Object {
+      "avatar_image": null,
+      "comped": false,
+      "created_at": StringMatching /\\\\d\\{4\\}-\\\\d\\{2\\}-\\\\d\\{2\\}T\\\\d\\{2\\}:\\\\d\\{2\\}:\\\\d\\{2\\}\\\\\\.000Z/,
+      "email": "with-product@test.com",
+      "email_count": 0,
+      "email_open_rate": null,
+      "email_opened_count": 0,
+      "geolocation": null,
+      "id": StringMatching /\\[a-f0-9\\]\\{24\\}/,
+      "labels": Array [],
+      "last_seen_at": StringMatching /\\\\d\\{4\\}-\\\\d\\{2\\}-\\\\d\\{2\\}T\\\\d\\{2\\}:\\\\d\\{2\\}:\\\\d\\{2\\}\\\\\\.000Z/,
+      "name": "Dana Barrett",
+      "newsletters": Array [],
+      "note": null,
+      "status": "paid",
+      "subscribed": false,
+      "subscriptions": Array [],
+      "updated_at": StringMatching /\\\\d\\{4\\}-\\\\d\\{2\\}-\\\\d\\{2\\}T\\\\d\\{2\\}:\\\\d\\{2\\}:\\\\d\\{2\\}\\\\\\.000Z/,
+      "uuid": "f6f91461-d7d8-4a3f-aa5d-8e582c40b347",
+    },
+    "previous": Object {
+      "last_seen_at": null,
+      "updated_at": StringMatching /\\\\d\\{4\\}-\\\\d\\{2\\}-\\\\d\\{2\\}T\\\\d\\{2\\}:\\\\d\\{2\\}:\\\\d\\{2\\}\\\\\\.000Z/,
+    },
+  },
+}
+`;

ghost/core/test/e2e-server/click-tracking.test.js

@@ -1,22 +1,25 @@
 const assert = require('assert/strict');
 const fetch = require('node-fetch').default;
-const {agentProvider, mockManager, fixtureManager} = require('../utils/e2e-framework');
+const {agentProvider, mockManager, fixtureManager, matchers} = require('../utils/e2e-framework');
 const urlUtils = require('../../core/shared/url-utils');
 const jobService = require('../../core/server/services/jobs/job-service');
+const {anyGhostAgent, anyContentVersion, anyNumber, anyISODateTime, anyObjectId} = matchers;
 
 describe('Click Tracking', function () {
     let agent;
+    let webhookMockReceiver;
 
     before(async function () {
         const {adminAgent} = await agentProvider.getAgentsWithFrontend();
         agent = adminAgent;
-        await fixtureManager.init('newsletters', 'members:newsletters');
+        await fixtureManager.init('newsletters', 'members:newsletters', 'integrations');
         await agent.loginAsOwner();
     });
 
     beforeEach(function () {
         mockManager.mockMail();
         mockManager.mockMailgun();
+        webhookMockReceiver = mockManager.mockWebhookRequests();
     });
 
     afterEach(function () {
@@ -51,6 +54,14 @@ describe('Click Tracking', function () {
         // Wait for the newsletter to be sent
         await jobService.allSettled();
 
+        // Setup a webhook listener for member.edited events
+        const webhookURL = 'https://test-webhook-receiver.com/member-edited/';
+        await webhookMockReceiver.mock(webhookURL);
+        await fixtureManager.insertWebhook({
+            event: 'member.edited',
+            url: webhookURL
+        });
+
         const {body: {links}} = await agent.get(
             `/links/?filter=${encodeURIComponent(`post_id:'${post.id}'`)}`
         );
@@ -99,7 +110,7 @@ describe('Click Tracking', function () {
 
         const linkToClick = links[0];
         const memberToClickLink = members[0];
-
+        assert(memberToClickLink.last_seen_at === null);
         const urlOfLinkToClick = new URL(linkToClick.link.from);
 
         urlOfLinkToClick.searchParams.set('m', memberToClickLink.uuid);
@@ -124,5 +135,34 @@ describe('Click Tracking', function () {
 
         assert(clickEvent);
         assert(previousClickCount + 1 === clickCount);
+
+        // Ensure we updated the member's last_seen_at
+        const {body: {members: [memberWhoClicked]}} = await agent.get(
+            `/members/${memberToClickLink.id}`
+        );
+        assert(memberWhoClicked.last_seen_at !== null, 'last_seen_at should be set after a click');
+        assert(new Date(memberWhoClicked.last_seen_at).getTime() > 0, 'last_seen_at should be a valid date');
+        // Ensure we sent the webhook with the correct payload, including newsletters and labels
+        await webhookMockReceiver.receivedRequest();
+        webhookMockReceiver
+            .matchHeaderSnapshot({
+                'content-version': anyContentVersion,
+                'content-length': anyNumber,
+                'user-agent': anyGhostAgent
+            })
+            .matchBodySnapshot({
+                member: {
+                    current: {
+                        created_at: anyISODateTime,
+                        id: anyObjectId,
+                        last_seen_at: anyISODateTime,
+                        updated_at: anyISODateTime
+                    },
+                    previous: {
+                        last_seen_at: null,
+                        updated_at: anyISODateTime
+                    }
+                }
+            });
     });
 });

ghost/members-events-service/lib/LastSeenAtUpdater.js

@@ -15,13 +15,15 @@ class LastSeenAtUpdater {
      * @param {any} deps.services.settingsCache The settings service
      * @param {() => object} deps.getMembersApi - A function which returns an instance of members-api
      * @param {any} deps.db Database connection
+     * @param {any} deps.events The event emitter
      */
     constructor({
         services: {
             settingsCache
         },
         getMembersApi,
-        db
+        db,
+        events
     }) {
         if (!getMembersApi) {
             throw new IncorrectUsageError({message: 'Missing option getMembersApi'});
@@ -30,6 +32,7 @@ class LastSeenAtUpdater {
         this._getMembersApi = getMembersApi;
         this._settingsCacheService = settingsCache;
         this._db = db;
+        this._events = events;
     }
     /**
      * Subscribe to events of this domainEvents service
@@ -104,17 +107,27 @@ class LastSeenAtUpdater {
      * - memberLastSeenAt is 2022-02-27 23:00:00, timestamp is current time, then `last_seen_at` is set to the current time
      * - memberLastSeenAt is 2022-02-28 01:00:00, timestamp is current time, then `last_seen_at` isn't changed
      * @param {string} memberId The id of the member to be udpated
-     * @param {string|null} memberLastSeenAt The previous last_seen_at property value for the current member
      * @param {Date} timestamp The event timestamp
      */
     async updateLastSeenAt(memberId, memberLastSeenAt, timestamp) {
         const timezone = this._settingsCacheService.get('timezone');
+        // First, check if memberLastSeenAt is null or before the beginning of the current day in the publication timezone
+        // This isn't strictly necessary since we will fetch the member row for update and double check this
+        // This is an optimization to avoid unnecessary database queries if last_seen_at is already after the beginning of the current day
         if (memberLastSeenAt === null || moment(moment.utc(timestamp).tz(timezone).startOf('day')).isAfter(memberLastSeenAt)) {
             const membersApi = this._getMembersApi();
-            await membersApi.members.update({
+            await this._db.knex.transaction(async (trx) => {
-                last_seen_at: moment.utc(timestamp).format('YYYY-MM-DD HH:mm:ss')
+                // To avoid a race condition, we lock the member row for update, then the last_seen_at field again to prevent simultaneous updates
-            }, {
+                const currentMember = await membersApi.members.get({id: memberId}, {require: true, transacting: trx, forUpdate: true});
-                id: memberId
+                const currentMemberLastSeenAt = currentMember.get('last_seen_at');
+                if (currentMemberLastSeenAt === null || moment(moment.utc(timestamp).tz(timezone).startOf('day')).isAfter(currentMemberLastSeenAt)) {
+                    const memberToUpdate = await currentMember.refresh({transacting: trx, forUpdate: false, withRelated: ['labels', 'newsletters']});
+                    const updatedMember = await memberToUpdate.save({last_seen_at: moment.utc(timestamp).format('YYYY-MM-DD HH:mm:ss')}, {transacting: trx, patch: true, method: 'update'});
+                    // The standard event doesn't get emitted inside the transaction, so we do it manually
+                    this._events.emit('member.edited', updatedMember);
+                    return Promise.resolve(updatedMember);
+                }
+                return Promise.resolve(undefined);
             });
         }
     }

ghost/members-events-service/test/last-seen-at-updater.test.js

@@ -6,11 +6,19 @@ const assert = require('assert/strict');
 const sinon = require('sinon');
 const {LastSeenAtUpdater} = require('../');
 const DomainEvents = require('@tryghost/domain-events');
-const {MemberPageViewEvent, MemberCommentEvent} = require('@tryghost/member-events');
+const {MemberPageViewEvent, MemberCommentEvent, MemberSubscribeEvent, MemberLinkClickEvent} = require('@tryghost/member-events');
 const moment = require('moment');
 const {EmailOpenedEvent} = require('@tryghost/email-events');
+const EventEmitter = require('events');
 
 describe('LastSeenAtUpdater', function () {
+    let events;
+
+    beforeEach(function () {
+        events = new EventEmitter();
+        DomainEvents.ee.removeAllListeners();
+    });
+
     it('Calls updateLastSeenAt on MemberPageViewEvents', async function () {
         const now = moment('2022-02-28T18:00:00Z').utc();
         const previousLastSeen = moment('2022-02-27T23:00:00Z').toISOString();
@@ -28,7 +36,8 @@ describe('LastSeenAtUpdater', function () {
                         update: stub
                     }
                 };
-            }
+            },
+            events
         });
         updater.subscribe(DomainEvents);
         sinon.stub(updater, 'updateLastSeenAt');
@@ -36,6 +45,32 @@ describe('LastSeenAtUpdater', function () {
         assert(updater.updateLastSeenAt.calledOnceWithExactly('1', previousLastSeen, now.toDate()));
     });
 
+    it('Calls updateLastSeenAt on MemberLinkClickEvents', async function () {
+        const now = moment('2022-02-28T18:00:00Z').utc();
+        const previousLastSeen = moment('2022-02-27T23:00:00Z').toISOString();
+        const stub = sinon.stub().resolves();
+        const settingsCache = sinon.stub().returns('Etc/UTC');
+        const updater = new LastSeenAtUpdater({
+            services: {
+                settingsCache: {
+                    get: settingsCache
+                }
+            },
+            getMembersApi() {
+                return {
+                    members: {
+                        update: stub
+                    }
+                };
+            },
+            events
+        });
+        updater.subscribe(DomainEvents);
+        sinon.stub(updater, 'updateLastSeenAt');
+        DomainEvents.dispatch(MemberLinkClickEvent.create({memberId: '1', memberLastSeenAt: previousLastSeen, url: '/'}, now.toDate()));
+        assert(updater.updateLastSeenAt.calledOnceWithExactly('1', previousLastSeen, now.toDate()));
+    });
+
     it('Calls updateLastSeenAt on email opened events', async function () {
         const now = moment('2022-02-28T18:00:00Z').utc();
         const settingsCache = sinon.stub().returns('Etc/UTC');
@@ -60,7 +95,8 @@ describe('LastSeenAtUpdater', function () {
             getMembersApi() {
                 return {};
             },
-            db
+            db,
+            events
         });
         updater.subscribe(DomainEvents);
         sinon.spy(updater, 'updateLastSeenAt');
@@ -87,7 +123,8 @@ describe('LastSeenAtUpdater', function () {
                         update: stub
                     }
                 };
-            }
+            },
+            events
         });
         updater.subscribe(DomainEvents);
         sinon.stub(updater, 'updateLastCommentedAt');
@@ -98,7 +135,11 @@ describe('LastSeenAtUpdater', function () {
     it('works correctly on another timezone (not updating last_seen_at)', async function () {
         const now = moment('2022-02-28T04:00:00Z').utc();
         const previousLastSeen = moment('2022-02-27T20:00:00Z').toISOString();
-        const stub = sinon.stub().resolves();
+        const transactionStub = sinon.stub().callsFake((callback) => {
+            return callback();
+        });
+        const saveStub = sinon.stub().resolves();
+        const getStub = sinon.stub().resolves({get: () => previousLastSeen, save: saveStub});
         const settingsCache = sinon.stub().returns('Asia/Bangkok');
         const updater = new LastSeenAtUpdater({
             services: {
@@ -109,13 +150,19 @@ describe('LastSeenAtUpdater', function () {
             getMembersApi() {
                 return {
                     members: {
-                        update: stub
+                        get: getStub
                     }
                 };
-            }
+            },
+            db: {
+                knex: {
+                    transaction: transactionStub
+                }
+            },
+            events
         });
         await updater.updateLastSeenAt('1', previousLastSeen, now.toDate());
-        assert(stub.notCalled, 'The LastSeenAtUpdater should attempt a member update when the new timestamp is within the same day in the publication timezone.');
+        assert(saveStub.notCalled, 'The LastSeenAtUpdater should attempt a member update when the new timestamp is within the same day in the publication timezone.');
     });
 
     it('works correctly on another timezone (not updating last_commented_at)', async function () {
@@ -143,7 +190,8 @@ describe('LastSeenAtUpdater', function () {
                         }
                     }
                 };
-            }
+            },
+            events
         });
         await updater.updateLastCommentedAt('1', now.toDate());
         assert(stub.notCalled, 'The LastSeenAtUpdater should attempt a member update when the new timestamp is within the same day in the publication timezone.');
@@ -152,7 +200,12 @@ describe('LastSeenAtUpdater', function () {
     it('works correctly on another timezone (updating last_seen_at)', async function () {
         const now = moment('2022-02-28T04:00:00Z').utc();
         const previousLastSeen = moment('2022-02-27T20:00:00Z').toISOString();
-        const stub = sinon.stub().resolves();
+        const transactionStub = sinon.stub().callsFake((callback) => {
+            return callback();
+        });
+        const saveStub = sinon.stub().resolves();
+        const refreshStub = sinon.stub().resolves({save: saveStub});
+        const getStub = sinon.stub().resolves({get: () => previousLastSeen, refresh: refreshStub});
         const settingsCache = sinon.stub().returns('Europe/Paris');
         const updater = new LastSeenAtUpdater({
             services: {
@@ -163,23 +216,32 @@ describe('LastSeenAtUpdater', function () {
             getMembersApi() {
                 return {
                     members: {
-                        update: stub
+                        get: getStub
                     }
                 };
-            }
+            },
+            db: {
+                knex: {
+                    transaction: transactionStub
+                }
+            },
+            events
         });
         await updater.updateLastSeenAt('1', previousLastSeen, now.toDate());
-        assert(stub.calledOnceWithExactly({
+        assert(saveStub.calledOnceWithExactly(
-            last_seen_at: now.format('YYYY-MM-DD HH:mm:ss')
+            sinon.match({last_seen_at: now.tz('utc').format('YYYY-MM-DD HH:mm:ss')}),
-        }, {
+            sinon.match({transacting: sinon.match.any, patch: true, method: 'update'})
-            id: '1'
+        ), 'The LastSeenAtUpdater should attempt a member update with the current date.');
-        }), 'The LastSeenAtUpdater should attempt a member update with the current date.');
     });
 
     it('Doesn\'t update when last_seen_at is too recent', async function () {
         const now = moment('2022-02-28T18:00:00Z');
         const previousLastSeen = moment('2022-02-28T00:00:00Z').toISOString();
-        const stub = sinon.stub().resolves();
+        const saveStub = sinon.stub().resolves();
+        const getStub = sinon.stub().resolves({get: () => previousLastSeen, save: saveStub});
+        const transactionStub = sinon.stub().callsFake((callback) => {
+            return callback();
+        });
         const settingsCache = sinon.stub().returns('Etc/UTC');
         const updater = new LastSeenAtUpdater({
             services: {
@@ -190,13 +252,19 @@ describe('LastSeenAtUpdater', function () {
             getMembersApi() {
                 return {
                     members: {
-                        update: stub
+                        get: getStub
                     }
                 };
-            }
+            },
+            db: {
+                knex: {
+                    transaction: transactionStub
+                }
+            },
+            events
         });
         await updater.updateLastSeenAt('1', previousLastSeen, now.toDate());
-        assert(stub.notCalled, 'The LastSeenAtUpdater should\'t update a member when the previous last_seen_at is close to the event timestamp.');
+        assert(saveStub.notCalled, 'The LastSeenAtUpdater should\'t update a member when the previous last_seen_at is close to the event timestamp.');
     });
 
     it('Doesn\'t update when last_commented_at is too recent', async function () {
@@ -224,7 +292,8 @@ describe('LastSeenAtUpdater', function () {
                         }
                     }
                 };
-            }
+            },
+            events
         });
         await updater.updateLastCommentedAt('1', now.toDate());
         assert(stub.notCalled, 'The LastSeenAtUpdater should\'t update a member');
@@ -255,7 +324,8 @@ describe('LastSeenAtUpdater', function () {
                         }
                     }
                 };
-            }
+            },
+            events
         });
         await updater.updateLastCommentedAt('1', now.toDate());
         assert(stub.notCalled, 'The LastSeenAtUpdater should\'t update a member.');
@@ -286,7 +356,8 @@ describe('LastSeenAtUpdater', function () {
                         }
                     }
                 };
-            }
+            },
+            events
         });
         await updater.updateLastCommentedAt('1', now.toDate());
         assert(stub.calledOnce, 'The LastSeenAtUpdater should attempt a member update');
@@ -324,7 +395,8 @@ describe('LastSeenAtUpdater', function () {
                         }
                     }
                 };
-            }
+            },
+            events
         });
         await updater.updateLastCommentedAt('1', now.toDate());
         assert(stub.calledOnce, 'The LastSeenAtUpdater should attempt a member update');
@@ -338,25 +410,26 @@ describe('LastSeenAtUpdater', function () {
     });
 
     it('Doesn\'t fire on other events', async function () {
-        const now = moment('2022-02-28T18:00:00Z');
+        const spy = sinon.spy();
-        const stub = sinon.stub().resolves();
-        const settingsCache = sinon.stub().returns('Etc/UTC');
         const updater = new LastSeenAtUpdater({
             services: {
                 settingsCache: {
-                    get: settingsCache
+                    get: () => 'Etc/UTC'
                 }
             },
             getMembersApi() {
                 return {
                     members: {
-                        update: stub
+                        update: spy
                     }
                 };
-            }
+            },
+            events
         });
-        await updater.updateLastSeenAt('1', undefined, now.toDate());
+        updater.subscribe(DomainEvents);
-        assert(stub.notCalled, 'The LastSeenAtUpdater should never fire on MemberPageViewEvent events.');
+        DomainEvents.dispatch(MemberSubscribeEvent.create({memberId: '1', source: 'api'}, new Date()));
+        await DomainEvents.allSettled();
+        assert(spy.notCalled, 'The LastSeenAtUpdater should never fire on MemberSubscribeEvent events.');
     });
 
     it('throws if getMembersApi is not passed to LastSeenAtUpdater', async function () {
@@ -372,4 +445,55 @@ describe('LastSeenAtUpdater', function () {
             });
         }, 'Missing option getMembersApi');
     });
+
+    it('avoids a race condition when updating last_seen_at', async function () {
+        const now = moment.utc('2022-02-28T18:00:00Z');
+        const saveStub = sinon.stub().resolves();
+        const refreshStub = sinon.stub().resolves({save: saveStub});
+        const settingsCache = sinon.stub().returns('Europe/Brussels');
+        const transactionStub = sinon.stub().callsFake((callback) => {
+            return callback();
+        });
+        const getStub = sinon.stub();
+        getStub.onFirstCall().resolves({get: () => null, save: saveStub, refresh: refreshStub});
+        getStub.onSecondCall().resolves({get: () => now.toDate(), save: saveStub, refresh: refreshStub});
+        getStub.resolves({get: () => now.toDate(), save: saveStub, refresh: refreshStub});
+        const updater = new LastSeenAtUpdater({
+            services: {
+                settingsCache: {
+                    get: settingsCache
+                }
+            },
+            getMembersApi() {
+                return {
+                    members: {
+                        get: getStub
+                    }
+                };
+            },
+            db: {
+                knex: {
+                    transaction: transactionStub
+                }
+            },
+            events
+        });
+        sinon.stub(events, 'emit');
+        await Promise.all([
+            updater.updateLastSeenAt('1', null, now.toDate()),
+            updater.updateLastSeenAt('1', null, now.toDate()),
+            updater.updateLastSeenAt('1', null, now.toDate()),
+            updater.updateLastSeenAt('1', null, now.toDate())
+        ]);
+        assert(saveStub.calledOnce, `The LastSeenAtUpdater should attempt a member update only once, but was called ${saveStub.callCount} times`);
+        assert(saveStub.calledOnceWithExactly(
+            sinon.match({last_seen_at: now.tz('utc').format('YYYY-MM-DD HH:mm:ss')}),
+            sinon.match({transacting: undefined, patch: true, method: 'update'})
+        ), 'The LastSeenAtUpdater should attempt a member update with the current date.');
+
+        assert(events.emit.calledOnceWithExactly(
+            'member.edited', 
+            sinon.match.any
+        ), 'The LastSeenAtUpdater should emit a member.edited event if it updated last_seen_at');
+    });
 });