From 276435f035b5cc6b94e60f90e575c089ff8d9bff Mon Sep 17 00:00:00 2001 From: Scott Nonnenberg Date: Thu, 4 Aug 2022 14:43:47 -0700 Subject: [PATCH] RoutineProfileRefresher: Track instances, only start() once, min sleep --- ts/routineProfileRefresh.ts | 58 ++++++++++++------- .../routineProfileRefresh_test.ts | 7 +++ 2 files changed, 44 insertions(+), 21 deletions(-) diff --git a/ts/routineProfileRefresh.ts b/ts/routineProfileRefresh.ts index ba9fd54f6db..d1a9ef792c9 100644 --- a/ts/routineProfileRefresh.ts +++ b/ts/routineProfileRefresh.ts @@ -14,7 +14,7 @@ import type { ConversationModel } from './models/conversations'; import type { StorageInterface } from './types/Storage.d'; import * as Errors from './types/errors'; import { getProfile } from './util/getProfile'; -import { MINUTE, HOUR, DAY, MONTH } from './util/durations'; +import { MINUTE, HOUR, DAY, WEEK, MONTH } from './util/durations'; const STORAGE_KEY = 'lastAttemptedToRefreshProfilesAt'; const MAX_AGE_TO_BE_CONSIDERED_ACTIVE = MONTH; @@ -23,8 +23,11 @@ const MAX_CONVERSATIONS_TO_REFRESH = 50; const MIN_ELAPSED_DURATION_TO_REFRESH_AGAIN = 12 * HOUR; const MIN_REFRESH_DELAY = MINUTE; +let idCounter = 1; + export class RoutineProfileRefresher { - private interval: NodeJS.Timeout | undefined; + private started = false; + private id: number; constructor( private readonly options: { @@ -32,12 +35,24 @@ export class RoutineProfileRefresher { getOurConversationId: () => string | undefined; storage: Pick; } - ) {} + ) { + // We keep track of how many of these classes we create, because we suspect that + // there might be too many... + idCounter += 1; + this.id = idCounter; + log.info( + `Creating new RoutineProfileRefresher instance with id ${this.id}` + ); + } public async start(): Promise { - if (this.interval !== undefined) { - clearInterval(this.interval); + const logId = `RoutineProfileRefresher.start/${this.id}`; + + if (this.started) { + log.warn(`${logId}: already started!`); + return; } + this.started = true; const { storage, getAllConversations, getOurConversationId } = this.options; @@ -45,14 +60,14 @@ export class RoutineProfileRefresher { while (true) { const refreshInMs = timeUntilNextRefresh(storage); - log.info(`routineProfileRefresh: waiting for ${refreshInMs}ms`); + log.info(`${logId}: waiting for ${refreshInMs}ms`); // eslint-disable-next-line no-await-in-loop await sleep(refreshInMs); const ourConversationId = getOurConversationId(); if (!ourConversationId) { - log.warn('routineProfileRefresh: missing our conversation id'); + log.warn(`${logId}: missing our conversation id`); // eslint-disable-next-line no-await-in-loop await sleep(MIN_REFRESH_DELAY); @@ -66,10 +81,11 @@ export class RoutineProfileRefresher { allConversations: getAllConversations(), ourConversationId, storage, + id: this.id, }); } catch (error) { - log.error('routineProfileRefresh: failure', Errors.toLogFormat(error)); - + log.error(`${logId}: failure`, Errors.toLogFormat(error)); + } finally { // eslint-disable-next-line no-await-in-loop await sleep(MIN_REFRESH_DELAY); } @@ -81,24 +97,26 @@ export async function routineProfileRefresh({ allConversations, ourConversationId, storage, - + id, // Only for tests getProfileFn = getProfile, }: { allConversations: ReadonlyArray; ourConversationId: string; storage: Pick; + id: number; getProfileFn?: typeof getProfile; }): Promise { - log.info('routineProfileRefresh: starting'); + const logId = `routineProfileRefresh/${id}`; + log.info(`${logId}: starting`); const refreshInMs = timeUntilNextRefresh(storage); if (refreshInMs > 0) { - log.info('routineProfileRefresh: too soon to refresh. Doing nothing'); + log.info(`${logId}: too soon to refresh. Doing nothing`); return; } - log.info('routineProfileRefresh: updating last refresh time'); + log.info(`${logId}: updating last refresh time`); await storage.put(STORAGE_KEY, Date.now()); const conversationsToRefresh = getConversationsToRefresh( @@ -106,7 +124,7 @@ export async function routineProfileRefresh({ ourConversationId ); - log.info('routineProfileRefresh: starting to refresh conversations'); + log.info(`${logId}: starting to refresh conversations`); let totalCount = 0; let successCount = 0; @@ -114,20 +132,18 @@ export async function routineProfileRefresh({ async function refreshConversation( conversation: ConversationModel ): Promise { - log.info( - `routineProfileRefresh: refreshing profile for ${conversation.idForLogging()}` - ); + log.info(`${logId}: refreshing profile for ${conversation.idForLogging()}`); totalCount += 1; try { await getProfileFn(conversation.get('uuid'), conversation.get('e164')); log.info( - `routineProfileRefresh: refreshed profile for ${conversation.idForLogging()}` + `${logId}: refreshed profile for ${conversation.idForLogging()}` ); successCount += 1; } catch (err) { log.error( - `routineProfileRefresh: refreshed profile for ${conversation.idForLogging()}`, + `${logId}: refreshed profile for ${conversation.idForLogging()}`, err?.stack || err ); } @@ -144,7 +160,7 @@ export async function routineProfileRefresh({ await refreshQueue.onIdle(); log.info( - `routineProfileRefresh: successfully refreshed ${successCount} out of ${totalCount} conversation(s)` + `${logId}: successfully refreshed ${successCount} out of ${totalCount} conversation(s)` ); } @@ -158,7 +174,7 @@ function timeUntilNextRefresh(storage: Pick): number { if (isNormalNumber(storedValue)) { const planned = storedValue + MIN_ELAPSED_DURATION_TO_REFRESH_AGAIN; const now = Date.now(); - return Math.max(0, planned - now); + return Math.min(Math.max(0, planned - now), WEEK); } assert( diff --git a/ts/test-electron/routineProfileRefresh_test.ts b/ts/test-electron/routineProfileRefresh_test.ts index ceaea31c8ae..f6152fe36fa 100644 --- a/ts/test-electron/routineProfileRefresh_test.ts +++ b/ts/test-electron/routineProfileRefresh_test.ts @@ -89,6 +89,7 @@ describe('routineProfileRefresh', () => { ourConversationId: UUID.generate().toString(), storage, getProfileFn, + id: 1, }); sinon.assert.notCalled(getProfileFn); @@ -104,6 +105,7 @@ describe('routineProfileRefresh', () => { ourConversationId: UUID.generate().toString(), storage: makeStorage(), getProfileFn, + id: 1, }); sinon.assert.calledWith( @@ -130,6 +132,7 @@ describe('routineProfileRefresh', () => { ourConversationId: UUID.generate().toString(), storage: makeStorage(), getProfileFn, + id: 1, }); sinon.assert.calledOnce(getProfileFn); @@ -159,6 +162,7 @@ describe('routineProfileRefresh', () => { ourConversationId: me.id, storage: makeStorage(), getProfileFn, + id: 1, }); sinon.assert.calledWith(getProfileFn, notMe.get('uuid'), notMe.get('e164')); @@ -176,6 +180,7 @@ describe('routineProfileRefresh', () => { ourConversationId: UUID.generate().toString(), storage: makeStorage(), getProfileFn, + id: 1, }); sinon.assert.calledOnce(getProfileFn); @@ -219,6 +224,7 @@ describe('routineProfileRefresh', () => { ourConversationId: UUID.generate().toString(), storage: makeStorage(), getProfileFn, + id: 1, }); sinon.assert.calledWith( @@ -288,6 +294,7 @@ describe('routineProfileRefresh', () => { ourConversationId: me.id, storage: makeStorage(), getProfileFn, + id: 1, }); [...activeConversations, ...inactiveGroupMembers].forEach(conversation => {