From ee9de52f9dfac8e81e74d0f1e527540fece84b31 Mon Sep 17 00:00:00 2001 From: Josh Perez Date: Tue, 29 Aug 2023 17:51:24 -0400 Subject: [PATCH] Add out of order mock test for read syncs --- ts/messageModifiers/ReadSyncs.ts | 22 +++- ts/messageModifiers/ViewSyncs.ts | 6 +- ts/test-mock/messaging/readSync_test.ts | 154 ++++++++++++++++++++++++ ts/util/modifyTargetMessage.ts | 6 + 4 files changed, 182 insertions(+), 6 deletions(-) create mode 100644 ts/test-mock/messaging/readSync_test.ts diff --git a/ts/messageModifiers/ReadSyncs.ts b/ts/messageModifiers/ReadSyncs.ts index 313724085..a267e8ccf 100644 --- a/ts/messageModifiers/ReadSyncs.ts +++ b/ts/messageModifiers/ReadSyncs.ts @@ -23,10 +23,10 @@ export type ReadSyncAttributesType = { timestamp: number; }; -const readSyncs = new Map(); +const readSyncs = new Map(); 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 { - 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 { }); 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 { // 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 { // 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 { ); } } 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 { 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)); } diff --git a/ts/messageModifiers/ViewSyncs.ts b/ts/messageModifiers/ViewSyncs.ts index d605950b8..aaf431e54 100644 --- a/ts/messageModifiers/ViewSyncs.ts +++ b/ts/messageModifiers/ViewSyncs.ts @@ -26,10 +26,10 @@ export type ViewSyncAttributesType = { viewedAt: number; }; -const viewSyncs = new Map(); +const viewSyncs = new Map(); 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 { - viewSyncs.set(sync.envelopeId, sync); + viewSyncs.set(sync.timestamp, sync); const logId = `ViewSyncs.onSync(timestamp=${sync.timestamp})`; diff --git a/ts/test-mock/messaging/readSync_test.ts b/ts/test-mock/messaging/readSync_test.ts new file mode 100644 index 000000000..08f7fc9c1 --- /dev/null +++ b/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) { + 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(); + }); +}); diff --git a/ts/util/modifyTargetMessage.ts b/ts/util/modifyTargetMessage.ts index 7c2dfbcf5..a7d308beb 100644 --- a/ts/util/modifyTargetMessage.ts +++ b/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);