From 0fe7e3039876c2922193185c0202252ca75993f3 Mon Sep 17 00:00:00 2001 From: Josh Perez <60019601+josh-signal@users.noreply.github.com> Date: Wed, 16 Sep 2020 14:04:28 -0400 Subject: [PATCH] Storage Service: More logging --- js/models/conversations.js | 3 + ts/services/storage.ts | 12 +++- ts/services/storageRecordOps.ts | 110 ++++++++++++++++++++++++-------- 3 files changed, 98 insertions(+), 27 deletions(-) diff --git a/js/models/conversations.js b/js/models/conversations.js index 63ce676130..cfa0a2c9d5 100644 --- a/js/models/conversations.js +++ b/js/models/conversations.js @@ -3100,6 +3100,9 @@ return; } + window.log.info( + `storageService[captureChange] marking ${this.debugID()} as needing sync` + ); this.set({ needsStorageServiceSync: true }); this.queueJob(() => { diff --git a/ts/services/storage.ts b/ts/services/storage.ts index c570e7b941..66768ee74b 100644 --- a/ts/services/storage.ts +++ b/ts/services/storage.ts @@ -567,7 +567,9 @@ async function mergeRecord( } } catch (err) { window.log.error( - `storageService.mergeRecord: merging record failed ${storageID}` + 'storageService.mergeRecord: merging record failed', + storageID, + err && err.stack ? err.stack : String(err) ); } @@ -696,9 +698,15 @@ async function processManifest( ); try { + window.log.info( + `storageService.processManifest: Attempting to merge ${decryptedStorageItems.length} records` + ); const mergedRecords = await pMap(decryptedStorageItems, mergeRecord, { concurrency: 5, }); + window.log.info( + `storageService.processManifest: Merged ${mergedRecords.length} records` + ); const unknownRecords: Map = new Map(); unknownRecordsArray.forEach((record: UnknownRecord) => { @@ -766,7 +774,7 @@ export async function runStorageServiceSyncJob(): Promise { // Guarding against no manifests being returned, everything should be ok if (!manifest) { window.log.info( - 'storageService.runStorageServiceSyncJob: no manifest, returning early' + 'storageService.runStorageServiceSyncJob: no new manifest' ); return; } diff --git a/ts/services/storageRecordOps.ts b/ts/services/storageRecordOps.ts index 6c0f6ba1af..84442f4a7a 100644 --- a/ts/services/storageRecordOps.ts +++ b/ts/services/storageRecordOps.ts @@ -1,5 +1,5 @@ /* tslint:disable no-backbone-get-set-outside-model */ -import { isEqual, isNumber } from 'lodash'; +import { isNumber } from 'lodash'; import { arrayBufferToBase64, @@ -43,6 +43,11 @@ function addUnknownFields( conversation: ConversationModelType ): void { if (record.__unknownFields) { + window.log.info( + `storageService.addUnknownFields: Unknown fields found for ${conversation.get( + 'id' + )}` + ); conversation.set({ storageUnknownFields: arrayBufferToBase64(record.__unknownFields), }); @@ -54,6 +59,11 @@ function applyUnknownFields( conversation: ConversationModelType ): void { if (conversation.get('storageUnknownFields')) { + window.log.info( + `storageService.applyUnknownFields: Applying unknown fields for ${conversation.get( + 'id' + )}` + ); // eslint-disable-next-line no-param-reassign record.__unknownFields = base64ToArrayBuffer( conversation.get('storageUnknownFields') @@ -200,6 +210,69 @@ function applyMessageRequestState( } } +type RecordClassObject = { + [key: string]: any; +}; + +function doRecordsConflict( + localRecord: RecordClassObject, + remoteRecord: RecordClassObject, + conversation: ConversationModelType +): boolean { + const debugID = conversation.debugID(); + + const localKeys = Object.keys(localRecord); + const remoteKeys = Object.keys(remoteRecord); + + if (localKeys.length !== remoteKeys.length) { + window.log.info( + 'storageService.doRecordsConflict: Local keys do not match remote keys', + debugID, + localKeys.join(','), + remoteKeys.join(',') + ); + return true; + } + + return localKeys.reduce((hasConflict: boolean, key: string): boolean => { + const localValue = localRecord[key]; + const remoteValue = remoteRecord[key]; + if (Object.prototype.toString.call(localValue) === '[object ArrayBuffer]') { + const isEqual = + arrayBufferToBase64(localValue) === arrayBufferToBase64(remoteValue); + if (!isEqual) { + window.log.info( + 'storageService.doRecordsConflict: Conflict found for', + key, + debugID + ); + } + return hasConflict || !isEqual; + } + + if (localValue === remoteValue) { + return hasConflict || false; + } + + // Sometimes we get `null` values from Protobuf and they should default to + // false, empty string, or 0 for these records we do not count them as + // conflicting. + if ( + remoteValue === null && + (localValue === false || localValue === '' || localValue === 0) + ) { + return hasConflict || false; + } + + window.log.info( + 'storageService.doRecordsConflict: Conflict found for', + key, + debugID + ); + return true; + }, false); +} + function doesRecordHavePendingChanges( mergedRecord: RecordClass, serviceRecord: RecordClass, @@ -207,21 +280,27 @@ function doesRecordHavePendingChanges( ): boolean { const shouldSync = Boolean(conversation.get('needsStorageServiceSync')); - const hasConflict = !isEqual(mergedRecord, serviceRecord); + if (!shouldSync) { + return false; + } - if (shouldSync && !hasConflict) { + const hasConflict = doRecordsConflict( + mergedRecord, + serviceRecord, + conversation + ); + + if (!hasConflict) { conversation.set({ needsStorageServiceSync: false }); } - return shouldSync && hasConflict; + return hasConflict; } export async function mergeGroupV1Record( storageID: string, groupV1Record: GroupV1RecordClass ): Promise { - window.log.info(`storageService.mergeGroupV1Record: merging ${storageID}`); - if (!groupV1Record.id) { window.log.info( `storageService.mergeGroupV1Record: no ID for ${storageID}` @@ -259,8 +338,6 @@ export async function mergeGroupV1Record( updateConversation(conversation.attributes); - window.log.info(`storageService.mergeGroupV1Record: merged ${storageID}`); - return hasPendingChanges; } @@ -268,8 +345,6 @@ export async function mergeGroupV2Record( storageID: string, groupV2Record: GroupV2RecordClass ): Promise { - window.log.info(`storageService.mergeGroupV2Record: merging ${storageID}`); - if (!groupV2Record.masterKey) { window.log.info( `storageService.mergeGroupV2Record: no master key for ${storageID}` @@ -334,7 +409,6 @@ export async function mergeGroupV2Record( conversation, dropInitialJoinMessage, }); - window.log.info(`storageService.mergeGroupV2Record: merged ${storageID}`); return hasPendingChanges; } @@ -343,8 +417,6 @@ export async function mergeContactRecord( storageID: string, contactRecord: ContactRecordClass ): Promise { - window.log.info(`storageService.mergeContactRecord: merging ${storageID}`); - window.normalizeUuids( contactRecord, ['serviceUuid'], @@ -414,8 +486,6 @@ export async function mergeContactRecord( updateConversation(conversation.attributes); - window.log.info(`storageService.mergeContactRecord: merged ${storageID}`); - return hasPendingChanges; } @@ -423,8 +493,6 @@ export async function mergeAccountRecord( storageID: string, accountRecord: AccountRecordClass ): Promise { - window.log.info(`storageService.mergeAccountRecord: merging ${storageID}`); - const { avatarUrl, linkPreviews, @@ -453,10 +521,6 @@ export async function mergeAccountRecord( window.storage.put('profileKey', profileKey.toArrayBuffer()); } - window.log.info( - `storageService.mergeAccountRecord: merged settings ${storageID}` - ); - const ourID = window.ConversationController.getOurConversationId(); if (!ourID) { @@ -494,9 +558,5 @@ export async function mergeAccountRecord( updateConversation(conversation.attributes); - window.log.info( - `storageService.mergeAccountRecord: merged profile ${storageID}` - ); - return hasPendingChanges; }