Add out of order mock test for read syncs

ts/messageModifiers/ReadSyncs.ts

@@ -23,10 +23,10 @@ export type ReadSyncAttributesType = {
   timestamp: number;
 };
 
-const readSyncs = new Map<string, ReadSyncAttributesType>();
+const readSyncs = new Map<number, ReadSyncAttributesType>();
 
 function remove(sync: ReadSyncAttributesType): void {
-  readSyncs.delete(sync.envelopeId);
+  readSyncs.delete(sync.timestamp);
   sync.removeFromMessageReceiverCache();
 }
 
@@ -41,10 +41,13 @@ async function maybeItIsAReactionReadSync(
   );
 
   if (!readReaction) {
+    log.info(`${logId}: ReadSync-3 ${sync.envelopeId}`);
     log.info(`${logId} not found:`, sync.senderId, sync.sender, sync.senderAci);
     return;
   }
 
+  log.info(`${logId}: ReadSync-4 ${sync.envelopeId}`);
+
   remove(sync);
 
   notificationService.removeBy({
@@ -86,10 +89,12 @@ export function forMessage(
 }
 
 export async function onSync(sync: ReadSyncAttributesType): Promise<void> {
-  readSyncs.set(sync.envelopeId, sync);
+  readSyncs.set(sync.timestamp, sync);
 
   const logId = `ReadSyncs.onSync(timestamp=${sync.timestamp})`;
 
+  log.info(`${logId}: ReadSync-1 ${sync.envelopeId}`);
+
   try {
     const messages = await window.Signal.Data.getMessagesBySentAt(
       sync.timestamp
@@ -106,10 +111,13 @@ export async function onSync(sync: ReadSyncAttributesType): Promise<void> {
     });
 
     if (!found) {
+      log.info(`${logId}: ReadSync-2 ${sync.envelopeId}`);
       await maybeItIsAReactionReadSync(sync);
       return;
     }
 
+    log.info(`${logId}: ReadSync-5 ${sync.envelopeId}`);
+
     notificationService.removeBy({ messageId: found.id });
 
     const message = window.MessageController.register(found.id, found);
@@ -119,10 +127,12 @@ export async function onSync(sync: ReadSyncAttributesType): Promise<void> {
     //   timer to the time specified by the read sync if it's earlier than
     //   the previous read time.
     if (isMessageUnread(message.attributes)) {
+      log.info(`${logId}: ReadSync-6 ${sync.envelopeId}`);
       // TODO DESKTOP-1509: use MessageUpdater.markRead once this is TS
       message.markRead(readAt, { skipSave: true });
 
       const updateConversation = async () => {
+        log.info(`${logId}: ReadSync-7 ${sync.envelopeId}`);
         // onReadMessage may result in messages older than this one being
         //   marked read. We want those messages to have the same expire timer
         //   start time as this one, so we pass the readAt value through.
@@ -131,8 +141,10 @@ export async function onSync(sync: ReadSyncAttributesType): Promise<void> {
 
       // only available during initialization
       if (StartupQueue.isAvailable()) {
+        log.info(`${logId}: ReadSync-8 ${sync.envelopeId}`);
         const conversation = message.getConversation();
         if (conversation) {
+          log.info(`${logId}: ReadSync-9 ${sync.envelopeId}`);
           StartupQueue.add(
             conversation.get('id'),
             message.get('sent_at'),
@@ -140,11 +152,13 @@ export async function onSync(sync: ReadSyncAttributesType): Promise<void> {
           );
         }
       } else {
+        log.info(`${logId}: ReadSync-10 ${sync.envelopeId}`);
         // not awaiting since we don't want to block work happening in the
         // eventHandlerQueue
         void updateConversation();
       }
     } else {
+      log.info(`${logId}: ReadSync-11 ${sync.envelopeId}`);
       const now = Date.now();
       const existingTimestamp = message.get('expirationStartTimestamp');
       const expirationStartTimestamp = Math.min(
@@ -154,10 +168,12 @@ export async function onSync(sync: ReadSyncAttributesType): Promise<void> {
       message.set({ expirationStartTimestamp });
     }
 
+    log.info(`${logId}: ReadSync-12 ${sync.envelopeId}`);
     queueUpdateMessage(message.attributes);
 
     remove(sync);
   } catch (error) {
+    log.info(`${logId}: ReadSync-13 ${sync.envelopeId}`);
     remove(sync);
     log.error(`${logId} error:`, Errors.toLogFormat(error));
   }

ts/messageModifiers/ViewSyncs.ts

@@ -26,10 +26,10 @@ export type ViewSyncAttributesType = {
   viewedAt: number;
 };
 
-const viewSyncs = new Map<string, ViewSyncAttributesType>();
+const viewSyncs = new Map<number, ViewSyncAttributesType>();
 
 function remove(sync: ViewSyncAttributesType): void {
-  viewSyncs.delete(sync.envelopeId);
+  viewSyncs.delete(sync.timestamp);
   sync.removeFromMessageReceiverCache();
 }
 
@@ -68,7 +68,7 @@ export function forMessage(
 }
 
 export async function onSync(sync: ViewSyncAttributesType): Promise<void> {
-  viewSyncs.set(sync.envelopeId, sync);
+  viewSyncs.set(sync.timestamp, sync);
 
   const logId = `ViewSyncs.onSync(timestamp=${sync.timestamp})`;
 

ts/test-mock/messaging/readSync_test.ts

@@ -0,0 +1,154 @@
+// Copyright 2023 Signal Messenger, LLC
+// SPDX-License-Identifier: AGPL-3.0-only
+
+import { assert } from 'chai';
+import createDebug from 'debug';
+import Long from 'long';
+
+import type { App } from '../playwright';
+import * as durations from '../../util/durations';
+import { Bootstrap } from '../bootstrap';
+
+export const debug = createDebug('mock:test:readSync');
+
+describe('readSync', function needsName() {
+  this.timeout(durations.MINUTE);
+
+  let bootstrap: Bootstrap;
+  let app: App;
+
+  beforeEach(async () => {
+    bootstrap = new Bootstrap();
+    await bootstrap.init();
+    app = await bootstrap.link();
+  });
+
+  afterEach(async function after() {
+    if (!bootstrap) {
+      return;
+    }
+
+    await bootstrap.maybeSaveLogs(this.currentTest, app);
+    await app.close();
+    await bootstrap.teardown();
+  });
+
+  it('applies out of order read syncs', async () => {
+    const { contacts, desktop, phone } = bootstrap;
+    const [friend] = contacts;
+
+    const page = await app.getWindow();
+
+    debug('incoming messages');
+    const timestamp1 = bootstrap.getTimestamp();
+    const timestamp2 = bootstrap.getTimestamp();
+    const timestamp3 = bootstrap.getTimestamp();
+    await friend.sendText(desktop, '૮₍˶•⤙•˶₎ა', {
+      timestamp: timestamp1,
+    });
+    await friend.sendText(desktop, '(੭｡╹▿╹｡)੭', {
+      timestamp: timestamp2,
+    });
+    await friend.sendText(desktop, '<(˶ᵔᵕᵔ˶)>', {
+      timestamp: timestamp3,
+    });
+
+    debug('checking left pane for unread count');
+    const leftPane = page.locator('#LeftPane');
+
+    await leftPane
+      .locator('.module-conversation-list__item--contact-or-conversation')
+      .first()
+      .waitFor();
+
+    debug('checking left pane for 3 unread');
+    const unreadCount = await leftPane
+      .locator(
+        '.module-conversation-list__item--contact-or-conversation__unread-indicator.module-conversation-list__item--contact-or-conversation__unread-indicator--unread-messages'
+      )
+      .first()
+      .innerText();
+    assert.equal(unreadCount, '3', 'unread count');
+
+    debug('incoming out of order messages');
+    const massTimestamps = Array.from(Array(100)).map(() =>
+      bootstrap.getTimestamp()
+    );
+    const readTimestamp = bootstrap.getTimestamp();
+    const unreadTimestamp = bootstrap.getTimestamp();
+
+    async function sendReadMessage() {
+      debug('sending read message', { timestamp: readTimestamp });
+      await friend.sendText(desktop, 'read marker', {
+        timestamp: readTimestamp,
+      });
+    }
+
+    async function sendUnreadMessage() {
+      debug('sending unread message', { timestamp: unreadTimestamp });
+      await friend.sendText(desktop, 'unread message', {
+        timestamp: unreadTimestamp,
+      });
+    }
+
+    async function sendReadSyncs(timestamps: Array<number>) {
+      debug('sending read syncs', { timestamps });
+
+      const sendOptions = {
+        timestamp: bootstrap.getTimestamp(),
+      };
+
+      const longTimestamps = timestamps.map(timestamp =>
+        Long.fromNumber(timestamp)
+      );
+
+      const senderAci = friend.device.aci;
+
+      await phone.sendRaw(
+        desktop,
+        {
+          syncMessage: {
+            read: longTimestamps.map(timestamp => ({
+              senderAci,
+              timestamp,
+            })),
+          },
+        },
+        sendOptions
+      );
+    }
+
+    await sendReadSyncs([timestamp2, timestamp3]);
+    await sendReadSyncs(massTimestamps);
+    await Promise.all(
+      massTimestamps.map(timestamp =>
+        friend.sendText(desktop, String(timestamp), {
+          timestamp,
+        })
+      )
+    );
+    await sendReadSyncs([readTimestamp, timestamp1]);
+    await sendReadMessage();
+    await sendUnreadMessage();
+
+    debug('checking left pane for 1 unread');
+    const newUnreadCount = await leftPane
+      .locator(
+        '.module-conversation-list__item--contact-or-conversation__unread-indicator.module-conversation-list__item--contact-or-conversation__unread-indicator--unread-messages'
+      )
+      .first()
+      .innerText();
+
+    assert.equal(newUnreadCount, '1', 'updated unread count');
+    debug({ newUnreadCount });
+
+    debug('opening conversation');
+    await leftPane
+      .locator('.module-conversation-list__item--contact-or-conversation')
+      .first()
+      .click();
+
+    debug('checking for latest message');
+    await page.locator('.module-message__text >> "unread message"').waitFor();
+  });
+});

ts/util/modifyTargetMessage.ts

@@ -111,10 +111,13 @@ export async function modifyTargetMessage(
 
     const viewSyncs = ViewSyncs.forMessage(message);
 
+    log.info(`${logId}: ReadSync-1`, { length: readSyncs.length });
+
     const isGroupStoryReply =
       isGroup(conversation.attributes) && message.get('storyId');
 
     if (readSyncs.length !== 0 || viewSyncs.length !== 0) {
+      log.info(`${logId}: ReadSync-2`);
       const markReadAt = Math.min(
         Date.now(),
         ...readSyncs.map(sync => sync.readAt),
@@ -149,6 +152,7 @@ export async function modifyTargetMessage(
       });
       changed = true;
 
+      log.info(`${logId}: ReadSync-3`);
       message.setPendingMarkRead(
         Math.min(message.getPendingMarkRead() ?? Date.now(), markReadAt)
       );
@@ -157,10 +161,12 @@ export async function modifyTargetMessage(
       !isGroupStoryReply &&
       canConversationBeUnarchived(conversation.attributes)
     ) {
+      log.info(`${logId}: ReadSync-4`);
       conversation.setArchived(false);
     }
 
     if (!isFirstRun && message.getPendingMarkRead()) {
+      log.info(`${logId}: ReadSync-5`);
       const markReadAt = message.getPendingMarkRead();
       message.setPendingMarkRead(undefined);