RoutineProfileRefresher: Track instances, only start() once, min sleep

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<StorageInterface, 'get' | 'put'>;
     }
-  ) {}
+  ) {
+    // 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<void> {
-    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<ConversationModel>;
   ourConversationId: string;
   storage: Pick<StorageInterface, 'get' | 'put'>;
+  id: number;
   getProfileFn?: typeof getProfile;
 }): Promise<void> {
-  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<void> {
-    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<StorageInterface, 'get'>): 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(

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 => {