5154e8d24f
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.
500 lines
19 KiB
JavaScript
500 lines
19 KiB
JavaScript
// Switch these lines once there are useful utils
|
|
// const testUtils = require('./utils');
|
|
require('./utils');
|
|
|
|
const assert = require('assert/strict');
|
|
const sinon = require('sinon');
|
|
const {LastSeenAtUpdater} = require('../');
|
|
const DomainEvents = require('@tryghost/domain-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();
|
|
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(MemberPageViewEvent.create({memberId: '1', memberLastSeenAt: previousLastSeen, url: '/'}, now.toDate()));
|
|
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');
|
|
const db = {
|
|
knex() {
|
|
return this;
|
|
},
|
|
where() {
|
|
return this;
|
|
},
|
|
andWhere() {
|
|
return this;
|
|
},
|
|
update: sinon.stub()
|
|
};
|
|
const updater = new LastSeenAtUpdater({
|
|
services: {
|
|
settingsCache: {
|
|
get: settingsCache
|
|
}
|
|
},
|
|
getMembersApi() {
|
|
return {};
|
|
},
|
|
db,
|
|
events
|
|
});
|
|
updater.subscribe(DomainEvents);
|
|
sinon.spy(updater, 'updateLastSeenAt');
|
|
sinon.spy(updater, 'updateLastSeenAtWithoutKnownLastSeen');
|
|
DomainEvents.dispatch(EmailOpenedEvent.create({memberId: '1', emailRecipientId: '1', emailId: '1', timestamp: now.toDate()}));
|
|
await DomainEvents.allSettled();
|
|
assert(updater.updateLastSeenAtWithoutKnownLastSeen.calledOnceWithExactly('1', now.toDate()));
|
|
assert(db.update.calledOnce);
|
|
});
|
|
|
|
it('Calls updateLastCommentedAt on MemberCommentEvents', async function () {
|
|
const now = moment('2022-02-28T18:00:00Z').utc();
|
|
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, 'updateLastCommentedAt');
|
|
DomainEvents.dispatch(MemberCommentEvent.create({memberId: '1'}, now.toDate()));
|
|
assert(updater.updateLastCommentedAt.calledOnceWithExactly('1', now.toDate()));
|
|
});
|
|
|
|
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 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: {
|
|
settingsCache: {
|
|
get: settingsCache
|
|
}
|
|
},
|
|
getMembersApi() {
|
|
return {
|
|
members: {
|
|
get: getStub
|
|
}
|
|
};
|
|
},
|
|
db: {
|
|
knex: {
|
|
transaction: transactionStub
|
|
}
|
|
},
|
|
events
|
|
});
|
|
await updater.updateLastSeenAt('1', previousLastSeen, now.toDate());
|
|
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 () {
|
|
const now = moment('2022-02-28T04:00:00Z').utc();
|
|
const previousLastSeen = moment('2022-02-27T20:00:00Z').toISOString();
|
|
const stub = sinon.stub().resolves();
|
|
const settingsCache = sinon.stub().returns('Asia/Bangkok');
|
|
const updater = new LastSeenAtUpdater({
|
|
services: {
|
|
settingsCache: {
|
|
get: settingsCache
|
|
}
|
|
},
|
|
getMembersApi() {
|
|
return {
|
|
members: {
|
|
update: stub,
|
|
get: () => {
|
|
return {
|
|
id: '1',
|
|
get: () => {
|
|
return previousLastSeen;
|
|
}
|
|
};
|
|
}
|
|
}
|
|
};
|
|
},
|
|
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.');
|
|
});
|
|
|
|
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 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: {
|
|
settingsCache: {
|
|
get: settingsCache
|
|
}
|
|
},
|
|
getMembersApi() {
|
|
return {
|
|
members: {
|
|
get: getStub
|
|
}
|
|
};
|
|
},
|
|
db: {
|
|
knex: {
|
|
transaction: transactionStub
|
|
}
|
|
},
|
|
events
|
|
});
|
|
await updater.updateLastSeenAt('1', previousLastSeen, now.toDate());
|
|
assert(saveStub.calledOnceWithExactly(
|
|
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'})
|
|
), '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 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: {
|
|
settingsCache: {
|
|
get: settingsCache
|
|
}
|
|
},
|
|
getMembersApi() {
|
|
return {
|
|
members: {
|
|
get: getStub
|
|
}
|
|
};
|
|
},
|
|
db: {
|
|
knex: {
|
|
transaction: transactionStub
|
|
}
|
|
},
|
|
events
|
|
});
|
|
await updater.updateLastSeenAt('1', previousLastSeen, now.toDate());
|
|
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 () {
|
|
const now = moment('2022-02-28T18:00:00Z');
|
|
const previousLastSeen = moment('2022-02-28T00:00:00Z').toDate();
|
|
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,
|
|
get: () => {
|
|
return {
|
|
id: '1',
|
|
get: () => {
|
|
return previousLastSeen;
|
|
}
|
|
};
|
|
}
|
|
}
|
|
};
|
|
},
|
|
events
|
|
});
|
|
await updater.updateLastCommentedAt('1', now.toDate());
|
|
assert(stub.notCalled, 'The LastSeenAtUpdater should\'t update a member');
|
|
});
|
|
|
|
it('Does not update when last_commented_at is same date in timezone', async function () {
|
|
const now = moment.utc('2022-02-28T18:00:00Z');
|
|
const previousLastSeen = moment.utc('2022-02-27T23:59:00Z').toDate();
|
|
const stub = sinon.stub().resolves();
|
|
const settingsCache = sinon.stub().returns('Europe/Brussels');
|
|
const updater = new LastSeenAtUpdater({
|
|
services: {
|
|
settingsCache: {
|
|
get: settingsCache
|
|
}
|
|
},
|
|
getMembersApi() {
|
|
return {
|
|
members: {
|
|
update: stub,
|
|
get: () => {
|
|
return {
|
|
id: '1',
|
|
get: () => {
|
|
return previousLastSeen;
|
|
}
|
|
};
|
|
}
|
|
}
|
|
};
|
|
},
|
|
events
|
|
});
|
|
await updater.updateLastCommentedAt('1', now.toDate());
|
|
assert(stub.notCalled, 'The LastSeenAtUpdater should\'t update a member.');
|
|
});
|
|
|
|
it('Does update when last_commented_at is different date', async function () {
|
|
const now = moment.utc('2022-02-28T18:00:00Z');
|
|
const previousLastSeen = moment.utc('2022-02-27T22:59:00Z').toDate();
|
|
const stub = sinon.stub().resolves();
|
|
const settingsCache = sinon.stub().returns('Europe/Brussels');
|
|
const updater = new LastSeenAtUpdater({
|
|
services: {
|
|
settingsCache: {
|
|
get: settingsCache
|
|
}
|
|
},
|
|
getMembersApi() {
|
|
return {
|
|
members: {
|
|
update: stub,
|
|
get: () => {
|
|
return {
|
|
id: '1',
|
|
get: () => {
|
|
return previousLastSeen;
|
|
}
|
|
};
|
|
}
|
|
}
|
|
};
|
|
},
|
|
events
|
|
});
|
|
await updater.updateLastCommentedAt('1', now.toDate());
|
|
assert(stub.calledOnce, 'The LastSeenAtUpdater should attempt a member update');
|
|
|
|
assert(stub.calledOnceWithExactly({
|
|
last_seen_at: now.tz('utc').format('YYYY-MM-DD HH:mm:ss'),
|
|
last_commented_at: now.tz('utc').format('YYYY-MM-DD HH:mm:ss')
|
|
}, {
|
|
id: '1'
|
|
}), 'The LastSeenAtUpdater should attempt a member update with the current date.');
|
|
});
|
|
|
|
it('Does update when last_commented_at is null', async function () {
|
|
const now = moment.utc('2022-02-28T18:00:00Z');
|
|
const previousLastSeen = null;
|
|
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,
|
|
get: () => {
|
|
return {
|
|
id: '1',
|
|
get: () => {
|
|
return previousLastSeen;
|
|
}
|
|
};
|
|
}
|
|
}
|
|
};
|
|
},
|
|
events
|
|
});
|
|
await updater.updateLastCommentedAt('1', now.toDate());
|
|
assert(stub.calledOnce, 'The LastSeenAtUpdater should attempt a member update');
|
|
|
|
assert(stub.calledOnceWithExactly({
|
|
last_seen_at: now.tz('utc').format('YYYY-MM-DD HH:mm:ss'),
|
|
last_commented_at: now.tz('utc').format('YYYY-MM-DD HH:mm:ss')
|
|
}, {
|
|
id: '1'
|
|
}), 'The LastSeenAtUpdater should attempt a member update with the current date.');
|
|
});
|
|
|
|
it('Doesn\'t fire on other events', async function () {
|
|
const spy = sinon.spy();
|
|
const updater = new LastSeenAtUpdater({
|
|
services: {
|
|
settingsCache: {
|
|
get: () => 'Etc/UTC'
|
|
}
|
|
},
|
|
getMembersApi() {
|
|
return {
|
|
members: {
|
|
update: spy
|
|
}
|
|
};
|
|
},
|
|
events
|
|
});
|
|
updater.subscribe(DomainEvents);
|
|
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 () {
|
|
const settingsCache = sinon.stub().returns('Asia/Bangkok');
|
|
|
|
should.throws(() => {
|
|
new LastSeenAtUpdater({
|
|
services: {
|
|
settingsCache: {
|
|
get: settingsCache
|
|
}
|
|
}
|
|
});
|
|
}, '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');
|
|
});
|
|
});
|