From e4db9358cf36305dcb39b6b1d404826dc51bd384 Mon Sep 17 00:00:00 2001 From: Josh Perez <60019601+josh-signal@users.noreply.github.com> Date: Tue, 6 Apr 2021 15:54:47 -0700 Subject: [PATCH] Storage service logging same --- ts/models/conversations.ts | 7 ---- ts/services/storage.ts | 39 ++++++++++++++++-- ts/services/storageRecordOps.ts | 72 ++++++++++++++++++--------------- ts/sql/Client.ts | 4 ++ ts/sql/Interface.ts | 4 +- 5 files changed, 80 insertions(+), 46 deletions(-) diff --git a/ts/models/conversations.ts b/ts/models/conversations.ts index a1e5cd2195..711b4cc5af 100644 --- a/ts/models/conversations.ts +++ b/ts/models/conversations.ts @@ -173,13 +173,6 @@ export class ConversationModel extends window.Backbone.Model< return `group(${groupId})`; } - debugID(): string { - const uuid = this.get('uuid'); - const e164 = this.get('e164'); - const groupId = this.get('groupId'); - return `group(${groupId}), sender(${uuid || e164}), id(${this.id})`; - } - // This is one of the few times that we want to collapse our uuid/e164 pair down into // just one bit of data. If we have a UUID, we'll send using it. getSendTarget(): string | undefined { diff --git a/ts/services/storage.ts b/ts/services/storage.ts index e4cf9e5df2..c3cc0b7564 100644 --- a/ts/services/storage.ts +++ b/ts/services/storage.ts @@ -70,6 +70,10 @@ function backOff(count: number) { return sleep(ms); } +function redactStorageID(storageID: string): string { + return storageID.substring(0, 3); +} + type RemoteRecord = { itemType: number; storageID: string; @@ -167,7 +171,7 @@ async function generateManifest( } else { window.log.info( 'storageService.generateManifest: unknown conversation', - conversation.debugID() + conversation.idForLogging() ); } @@ -201,8 +205,25 @@ async function generateManifest( if (isNewItem) { newItems.add(storageItem); + if (storageID) { + window.log.info( + 'storageService.generateManifest: new key', + conversation.idForLogging(), + redactStorageID(storageID) + ); + } else { + window.log.info( + 'storageService.generateManifest: no storage id', + conversation.idForLogging() + ); + } + const oldStorageID = conversation.get('storageID'); if (oldStorageID) { + window.log.info( + 'storageService.generateManifest: deleting key', + redactStorageID(oldStorageID) + ); deleteKeys.push(base64ToArrayBuffer(oldStorageID)); } @@ -313,7 +334,7 @@ async function generateManifest( if (storageKeyDuplicates.has(storageID)) { window.log.info( 'storageService.generateManifest: removing duplicate identifier from inserts', - storageID + redactStorageID(storageID) ); newItems.delete(storageItem); } @@ -594,11 +615,17 @@ async function mergeRecord( isUnsupported = true; window.log.info('storageService.mergeRecord: Unknown record:', itemType); } + window.log.info( + 'storageService.mergeRecord: merged', + redactStorageID(storageID), + itemType, + hasConflict + ); } catch (err) { hasError = true; window.log.error( 'storageService.mergeRecord: Error with', - storageID, + redactStorageID(storageID), itemType ); } @@ -663,6 +690,10 @@ async function processManifest( const remoteOnlyRecords = new Map(); remoteOnlySet.forEach(storageID => { + window.log.info( + 'storageService.processManifest: remote key', + redactStorageID(storageID) + ); remoteOnlyRecords.set(storageID, { storageID, itemType: remoteKeysTypeMap.get(storageID), @@ -865,7 +896,7 @@ async function processRemoteRecords( if (storageID && !remoteOnlyRecords.has(storageID)) { window.log.info( 'storageService.processRemoteRecords: clearing storageID', - conversation.debugID() + conversation.idForLogging() ); conversation.unset('storageID'); } diff --git a/ts/services/storageRecordOps.ts b/ts/services/storageRecordOps.ts index 50e760a928..ad1abccfc6 100644 --- a/ts/services/storageRecordOps.ts +++ b/ts/services/storageRecordOps.ts @@ -1,7 +1,7 @@ // Copyright 2020-2021 Signal Messenger, LLC // SPDX-License-Identifier: AGPL-3.0-only -import { isNumber } from 'lodash'; +import { isEqual, isNumber } from 'lodash'; import { arrayBufferToBase64, @@ -64,7 +64,7 @@ function addUnknownFields( if (record.__unknownFields) { window.log.info( 'storageService.addUnknownFields: Unknown fields found for', - conversation.debugID() + conversation.idForLogging() ); conversation.set({ storageUnknownFields: arrayBufferToBase64(record.__unknownFields), @@ -74,7 +74,7 @@ function addUnknownFields( // saved locally then we need to clear it out window.log.info( 'storageService.addUnknownFields: Clearing unknown fields for', - conversation.debugID() + conversation.idForLogging() ); conversation.unset('storageUnknownFields'); } @@ -256,7 +256,8 @@ export async function toAccountRecord( ); window.log.info( - `toAccountRecord: sending ${pinnedConversations.length} pinned conversations` + 'storageService.toAccountRecord: pinnedConversations', + pinnedConversations.length ); accountRecord.pinnedConversations = pinnedConversations; @@ -344,7 +345,7 @@ function doRecordsConflict( remoteRecord: RecordClassObject, conversation: ConversationModel ): boolean { - const debugID = conversation.debugID(); + const idForLogging = conversation.idForLogging(); const localKeys = Object.keys(localRecord); const remoteKeys = Object.keys(remoteRecord); @@ -352,7 +353,7 @@ function doRecordsConflict( if (localKeys.length !== remoteKeys.length) { window.log.info( 'storageService.doRecordsConflict: Local keys do not match remote keys', - debugID, + idForLogging, localKeys.join(','), remoteKeys.join(',') ); @@ -362,18 +363,6 @@ function doRecordsConflict( 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; @@ -389,12 +378,17 @@ function doRecordsConflict( return hasConflict || false; } - window.log.info( - 'storageService.doRecordsConflict: Conflict found for', - key, - debugID - ); - return true; + const areEqual = isEqual(localValue, remoteValue); + + if (!areEqual) { + window.log.info( + 'storageService.doRecordsConflict: Conflict found for', + key, + idForLogging + ); + } + + return !areEqual; }, false); } @@ -442,7 +436,9 @@ export async function mergeGroupV1Record( // Here we ensure that the record we're about to process is GV1 otherwise // we drop the update. if (conversation && !conversation.isGroupV1()) { - throw new Error(`Record has group type mismatch ${conversation.debugID()}`); + throw new Error( + `Record has group type mismatch ${conversation.idForLogging()}` + ); } if (!conversation) { @@ -462,7 +458,7 @@ export async function mergeGroupV1Record( if (conversation) { window.log.info( 'storageService.mergeGroupV1Record: found existing group', - conversation.debugID() + conversation.idForLogging() ); } else { conversation = await window.ConversationController.getOrCreateAndWait( @@ -471,7 +467,7 @@ export async function mergeGroupV1Record( ); window.log.info( 'storageService.mergeGroupV1Record: created a new group locally', - conversation.debugID() + conversation.idForLogging() ); } @@ -500,7 +496,7 @@ export async function mergeGroupV1Record( window.log.info( 'storageService.mergeGroupV1Record marking v1 ' + ' group for an update to v2', - conversation.debugID() + conversation.idForLogging() ); // We want to upgrade group in the storage after merging it. @@ -570,7 +566,10 @@ export async function mergeGroupV2Record( const masterKeyBuffer = groupV2Record.masterKey.toArrayBuffer(); const conversation = await getGroupV2Conversation(masterKeyBuffer); - window.log.info('storageService.mergeGroupV2Record:', conversation.debugID()); + window.log.info( + 'storageService.mergeGroupV2Record:', + conversation.idForLogging() + ); conversation.set({ isArchived: Boolean(groupV2Record.archived), @@ -647,7 +646,10 @@ export async function mergeContactRecord( 'private' ); - window.log.info('storageService.mergeContactRecord:', conversation.debugID()); + window.log.info( + 'storageService.mergeContactRecord:', + conversation.idForLogging() + ); if (contactRecord.profileKey) { await conversation.setProfileKey( @@ -706,7 +708,7 @@ export async function mergeAccountRecord( noteToSelfArchived, noteToSelfMarkedUnread, phoneNumberSharingMode, - pinnedConversations: remotelyPinnedConversationClasses, + pinnedConversations, profileKey, readReceipts, sealedSenderIndicators, @@ -761,7 +763,7 @@ export async function mergeAccountRecord( window.storage.put('profileKey', profileKey.toArrayBuffer()); } - if (remotelyPinnedConversationClasses) { + if (pinnedConversations) { const modelPinnedConversations = window .getConversations() .filter(conversation => Boolean(conversation.get('isPinned'))); @@ -795,8 +797,12 @@ export async function mergeAccountRecord( 'storageService.mergeAccountRecord: Local pinned', locallyPinnedConversations.length ); + window.log.info( + 'storageService.mergeAccountRecord: Remote pinned', + pinnedConversations.length + ); - const remotelyPinnedConversationPromises = remotelyPinnedConversationClasses.map( + const remotelyPinnedConversationPromises = pinnedConversations.map( async pinnedConversation => { let conversationId; let conversationType: ConversationAttributesTypeType = 'private'; diff --git a/ts/sql/Client.ts b/ts/sql/Client.ts index f853cd943d..e145a4cd93 100644 --- a/ts/sql/Client.ts +++ b/ts/sql/Client.ts @@ -746,6 +746,10 @@ async function getConversationById( ) { const data = await channels.getConversationById(id); + if (!data) { + return undefined; + } + return new Conversation(data); } diff --git a/ts/sql/Interface.ts b/ts/sql/Interface.ts index d2763a96d1..4921a17192 100644 --- a/ts/sql/Interface.ts +++ b/ts/sql/Interface.ts @@ -203,7 +203,7 @@ export type ServerInterface = DataInterface & { getAllConversations: () => Promise>; getAllGroupsInvolvingId: (id: string) => Promise>; getAllPrivateConversations: () => Promise>; - getConversationById: (id: string) => Promise; + getConversationById: (id: string) => Promise; getExpiredMessages: () => Promise>; getMessageById: (id: string) => Promise; getMessageBySender: (options: { @@ -291,7 +291,7 @@ export type ClientInterface = DataInterface & { getConversationById: ( id: string, options: { Conversation: typeof ConversationModel } - ) => Promise; + ) => Promise; getExpiredMessages: (options: { MessageCollection: typeof MessageModelCollectionType; }) => Promise;