Fixed race condition when updating member's last_seen_at timestamp

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({
-                last_seen_at: moment.utc(timestamp).format('YYYY-MM-DD HH:mm:ss')
-            }, {
-                id: memberId
+            await this._db.knex.transaction(async (trx) => {
+                // 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});
+                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);
             });
         }
     }