jonny
/
Signal-Desktop
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Improve logging in handleDataMessage and contact sync

This commit is contained in:
Scott Nonnenberg 2022-09-13 21:09:28 -07:00 committed by GitHub
parent 4cb52b75f2
commit 1f010c75c6
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
4 changed files with 40 additions and 51 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

70
ts/models/messages.ts
View File

@ -2065,11 +2065,9 @@ export class MessageModel extends window.Backbone.Model<MessageAttributesType> {
// eslint-disable-next-line @typescript-eslint/no-non-null-assertion
const conversation = window.ConversationController.get(conversationId)!;
const idLog = conversation.idForLogging();
const idLog = `handleDataMessage/${conversation.idForLogging()} ${message.idForLogging()}`;
await conversation.queueJob('handleDataMessage', async () => {
log.info(
`handleDataMessage/${idLog}: processing message ${message.idForLogging()}`
);
log.info(`${idLog}: starting processing in queue`);
if (
isStory(message.attributes) &&
@ -2078,7 +2076,7 @@ export class MessageModel extends window.Backbone.Model<MessageAttributesType> {
})
) {
log.info(
`handleDataMessage/${idLog}: dropping story from !accepted`,
`${idLog}: dropping story from !accepted`,
this.getSenderIdentifier()
);
confirm();
@ -2090,13 +2088,10 @@ export class MessageModel extends window.Backbone.Model<MessageAttributesType> {
this.getSenderIdentifier()
)?.attributes;
if (inMemoryMessage) {
log.info(
`handleDataMessage/${idLog}: cache hit`,
this.getSenderIdentifier()
);
log.info(`${idLog}: cache hit`, this.getSenderIdentifier());
} else {
log.info(
`handleDataMessage/${idLog}: duplicate check db lookup needed`,
`${idLog}: duplicate check db lookup needed`,
this.getSenderIdentifier()
);
}
@ -2112,17 +2107,14 @@ export class MessageModel extends window.Backbone.Model<MessageAttributesType> {
this.attributes.storyDistributionListId));
if (isDuplicateMessage) {
log.warn(
`handleDataMessage/${idLog}: Received duplicate message`,
this.idForLogging()
);
log.warn(`${idLog}: Received duplicate message`, this.idForLogging());
confirm();
return;
}
if (type === 'outgoing') {
if (isUpdate && existingMessage) {
log.info(
`handleDataMessage/${idLog}: Updating message ${message.idForLogging()} with received transcript`
`${idLog}: Updating message ${message.idForLogging()} with received transcript`
);
const toUpdate = window.MessageController.register(
@ -2198,7 +2190,7 @@ export class MessageModel extends window.Backbone.Model<MessageAttributesType> {
}
if (isUpdate) {
log.warn(
`handleDataMessage/${idLog}: Received update transcript, but no existing entry for message ${message.idForLogging()}. Dropping.`
`${idLog}: Received update transcript, but no existing entry for message ${message.idForLogging()}. Dropping.`
);
confirm();
@ -2206,7 +2198,7 @@ export class MessageModel extends window.Backbone.Model<MessageAttributesType> {
}
if (existingMessage) {
log.warn(
`handleDataMessage/${idLog}: Received duplicate transcript for message ${message.idForLogging()}, but it was not an update transcript. Dropping.`
`${idLog}: Received duplicate transcript for message ${message.idForLogging()}, but it was not an update transcript. Dropping.`
);
confirm();
@ -2273,7 +2265,7 @@ export class MessageModel extends window.Backbone.Model<MessageAttributesType> {
} catch (error) {
const errorText = error && error.stack ? error.stack : error;
log.error(
`handleDataMessage/${idLog}: Failed to process group update as part of message ${message.idForLogging()}: ${errorText}`
`${idLog}: Failed to process group update as part of message ${message.idForLogging()}: ${errorText}`
);
throw error;
}
@ -2300,7 +2292,7 @@ export class MessageModel extends window.Backbone.Model<MessageAttributesType> {
(sourceUuid && window.storage.blocked.isUuidBlocked(sourceUuid));
if (isBlocked) {
log.info(
`handleDataMessage/${idLog}: Dropping message from blocked sender. hasGroupV2Prop: ${hasGroupV2Prop}`
`${idLog}: Dropping message from blocked sender. hasGroupV2Prop: ${hasGroupV2Prop}`
);
confirm();
@ -2320,7 +2312,7 @@ export class MessageModel extends window.Backbone.Model<MessageAttributesType> {
(sourceUuid && !conversation.hasMember(new UUID(sourceUuid))))
) {
log.warn(
`Received message destined for group ${conversation.idForLogging()}, which we or the sender are not a part of. Dropping.`
`${idLog}: Received message destined for group, which we or the sender are not a part of. Dropping.`
);
confirm();
return;
@ -2396,7 +2388,7 @@ export class MessageModel extends window.Backbone.Model<MessageAttributesType> {
if (initialMessage.storyContext && !storyQuote) {
log.warn(
`handleDataMessage/${idLog}: Received storyContext message but no matching story. Dropping.`
`${idLog}: Received storyContext message but no matching story. Dropping.`
);
confirm();
@ -2518,7 +2510,7 @@ export class MessageModel extends window.Backbone.Model<MessageAttributesType> {
hash = computeHash(loadedAttachment.data);
}
} catch (err) {
log.info('handleDataMessage: group avatar download failed');
log.info(`${idLog}: group avatar download failed`);
}
}
@ -2558,7 +2550,7 @@ export class MessageModel extends window.Backbone.Model<MessageAttributesType> {
pendingGroupUpdate.avatarUpdated = true;
} else {
log.info(
'handleDataMessage: Group avatar hash matched; not replacing group avatar'
`${idLog}: Group avatar hash matched; not replacing group avatar`
);
}
@ -2588,7 +2580,7 @@ export class MessageModel extends window.Backbone.Model<MessageAttributesType> {
if (!inGroup) {
const senderString = sender ? sender.idForLogging() : null;
log.info(
`Got 'left' message from someone not in group: ${senderString}. Dropping.`
`${idLog}: Got 'left' message from someone not in group: ${senderString}. Dropping.`
);
return;
}
@ -2614,9 +2606,7 @@ export class MessageModel extends window.Backbone.Model<MessageAttributesType> {
// message.set call and after GroupV1 processing to make sure all possible
// properties are set before we determine that a message is empty.
if (message.isEmpty()) {
log.info(
`handleDataMessage: Dropping empty message ${message.idForLogging()} in conversation ${conversation.idForLogging()}`
);
log.info(`${idLog}: Dropping empty message`);
confirm();
return;
}
@ -2650,7 +2640,7 @@ export class MessageModel extends window.Backbone.Model<MessageAttributesType> {
log.info('Incoming expirationTimerUpdate changed timer', {
id: conversation.idForLogging(),
expireTimer: dataMessage.expireTimer || 'disabled',
source: 'handleDataMessage/expirationTimerUpdate',
source: idLog,
});
conversation.set({
expireTimer: dataMessage.expireTimer,
@ -2668,7 +2658,7 @@ export class MessageModel extends window.Backbone.Model<MessageAttributesType> {
receivedAtMS: message.get('received_at_ms'),
sentAt: message.get('sent_at'),
fromGroupUpdate: isGroupUpdate(message.attributes),
reason: `handleDataMessage(${this.idForLogging()})`,
reason: idLog,
});
} else if (
// We won't turn off timers for these kinds of messages:
@ -2680,7 +2670,7 @@ export class MessageModel extends window.Backbone.Model<MessageAttributesType> {
receivedAt: message.get('received_at'),
receivedAtMS: message.get('received_at_ms'),
sentAt: message.get('sent_at'),
reason: `handleDataMessage(${this.idForLogging()})`,
reason: idLog,
});
}
}
@ -2714,7 +2704,7 @@ export class MessageModel extends window.Backbone.Model<MessageAttributesType> {
!message.isValidTapToView()
) {
log.warn(
`Received tap to view message ${message.idForLogging()} with invalid data. Erasing contents.`
`${idLog}: Received tap to view message with invalid data. Erasing contents.`
);
message.set({
isTapToViewInvalid: true,
@ -2759,7 +2749,7 @@ export class MessageModel extends window.Backbone.Model<MessageAttributesType> {
);
const { messaging } = window.textsecure;
if (!messaging) {
throw new Error('handleDataMessage: messaging is not available');
throw new Error(`${idLog}: messaging is not available`);
}
const response = await messaging.server.getBoostBadgesFromServer(
userLanguages
@ -2771,7 +2761,7 @@ export class MessageModel extends window.Backbone.Model<MessageAttributesType> {
const badge = boostBadgesByLevel[level];
if (!badge) {
log.error(
`handleDataMessage: gift badge with level ${level} not found on server`
`${idLog}: gift badge with level ${level} not found on server`
);
} else {
await window.reduxActions.badges.updateOrCreate([badge]);
@ -2806,7 +2796,7 @@ export class MessageModel extends window.Backbone.Model<MessageAttributesType> {
if (window.attachmentDownloadQueue) {
window.attachmentDownloadQueue.unshift(message);
log.info(
'Adding to attachmentDownloadQueue',
`${idLog}: Adding to attachmentDownloadQueue`,
message.get('sent_at')
);
} else {
@ -2817,19 +2807,11 @@ export class MessageModel extends window.Backbone.Model<MessageAttributesType> {
const isFirstRun = true;
await this.modifyTargetMessage(conversation, isFirstRun);
log.info(
'handleDataMessage: Batching save for',
message.get('sent_at')
);
log.info(`${idLog}: Batching save`);
this.saveAndNotify(conversation, confirm);
} catch (error) {
const errorForLog = error && error.stack ? error.stack : error;
log.error(
'handleDataMessage',
message.idForLogging(),
'error:',
errorForLog
);
log.error(`${idLog}: error:`, errorForLog);
throw error;
}
});

15
ts/services/contactSync.ts
View File

@ -28,7 +28,8 @@ export function setIsInitialSync(newValue: boolean): void {
async function updateConversationFromContactSync(
conversation: ConversationModel,
details: ModifiedContactDetails,
receivedAtCounter: number
receivedAtCounter: number,
sentAt: number
): Promise<void> {
const { writeNewAttachmentData, deleteAttachmentData, doesAttachmentExist } =
window.Signal.Migrations;
@ -67,7 +68,7 @@ async function updateConversationFromContactSync(
receivedAt: receivedAtCounter,
fromSync: true,
isInitialSync,
reason: 'contact sync',
reason: `contact sync (sent=${sentAt})`,
});
window.Whisper.events.trigger('incrementProgress');
@ -79,6 +80,7 @@ async function doContactSync({
contacts,
complete,
receivedAtCounter,
sentAt,
}: ContactSyncEvent): Promise<void> {
// iOS sets `syncMessage.contacts.complete` flag to `true` unconditionally
// and so we have to employ tricks to figure out whether the sync is full or
@ -93,7 +95,7 @@ async function doContactSync({
window.storage.user.getUuid()?.toString()
);
const logId = `doContactSync(${receivedAtCounter}, isFullSync=${isFullSync})`;
const logId = `doContactSync(sent=${sentAt}, receivedAt=${receivedAtCounter}, isFullSync=${isFullSync})`;
log.info(`${logId}: got ${contacts.length} contacts`);
const updatedConversations = new Set<ConversationModel>();
@ -130,7 +132,8 @@ async function doContactSync({
await updateConversationFromContactSync(
conversation,
details,
receivedAtCounter
receivedAtCounter,
sentAt
);
updatedConversations.add(conversation);
@ -187,6 +190,8 @@ async function doContactSync({
}
export async function onContactSync(ev: ContactSyncEvent): Promise<void> {
log.info(`onContactSync(${ev.receivedAtCounter}): queueing sync`);
log.info(
`onContactSync(sent=${ev.sentAt}, receivedAt=${ev.receivedAtCounter}): queueing sync`
);
await queue.add(() => doContactSync(ev));
}

3
ts/textsecure/MessageReceiver.ts
View File

@ -3071,7 +3071,8 @@ export default class MessageReceiver
const contactSync = new ContactSyncEvent(
Array.from(contactBuffer),
Boolean(contacts.complete),
envelope.receivedAtCounter
envelope.receivedAtCounter,
envelope.timestamp
);
await this.dispatchAndWait(contactSync);

3
ts/textsecure/messageReceiverEvents.ts
View File

@ -77,7 +77,8 @@ export class ContactSyncEvent extends Event {
constructor(
public readonly contacts: ReadonlyArray<ModifiedContactDetails>,
public readonly complete: boolean,
public readonly receivedAtCounter: number
public readonly receivedAtCounter: number,
public readonly sentAt: number
) {
super('contactSync');
}