From bad1cc1571da19bb664cbc1087873649d809cc71 Mon Sep 17 00:00:00 2001 From: Greyson Parrelli Date: Tue, 21 Dec 2021 10:48:00 -0500 Subject: [PATCH] Improve logging around message processing. --- .../messages/MessageContentProcessor.java | 96 +++++++++++++++---- 1 file changed, 76 insertions(+), 20 deletions(-) diff --git a/app/src/main/java/org/thoughtcrime/securesms/messages/MessageContentProcessor.java b/app/src/main/java/org/thoughtcrime/securesms/messages/MessageContentProcessor.java index e3bc86fd11..3c40b1361b 100644 --- a/app/src/main/java/org/thoughtcrime/securesms/messages/MessageContentProcessor.java +++ b/app/src/main/java/org/thoughtcrime/securesms/messages/MessageContentProcessor.java @@ -297,16 +297,16 @@ public final class MessageContentProcessor { SignalServiceSyncMessage syncMessage = content.getSyncMessage().get(); if (syncMessage.getSent().isPresent()) handleSynchronizeSentMessage(content, syncMessage.getSent().get(), senderRecipient); - else if (syncMessage.getRequest().isPresent()) handleSynchronizeRequestMessage(syncMessage.getRequest().get()); + else if (syncMessage.getRequest().isPresent()) handleSynchronizeRequestMessage(syncMessage.getRequest().get(), content.getTimestamp()); else if (syncMessage.getRead().isPresent()) handleSynchronizeReadMessage(syncMessage.getRead().get(), content.getTimestamp(), senderRecipient); else if (syncMessage.getViewed().isPresent()) handleSynchronizeViewedMessage(syncMessage.getViewed().get(), content.getTimestamp()); else if (syncMessage.getViewOnceOpen().isPresent()) handleSynchronizeViewOnceOpenMessage(syncMessage.getViewOnceOpen().get(), content.getTimestamp()); else if (syncMessage.getVerified().isPresent()) handleSynchronizeVerifiedMessage(syncMessage.getVerified().get()); - else if (syncMessage.getStickerPackOperations().isPresent()) handleSynchronizeStickerPackOperation(syncMessage.getStickerPackOperations().get()); - else if (syncMessage.getConfiguration().isPresent()) handleSynchronizeConfigurationMessage(syncMessage.getConfiguration().get()); + else if (syncMessage.getStickerPackOperations().isPresent()) handleSynchronizeStickerPackOperation(syncMessage.getStickerPackOperations().get(), content.getTimestamp()); + else if (syncMessage.getConfiguration().isPresent()) handleSynchronizeConfigurationMessage(syncMessage.getConfiguration().get(), content.getTimestamp()); else if (syncMessage.getBlockedList().isPresent()) handleSynchronizeBlockedListMessage(syncMessage.getBlockedList().get()); - else if (syncMessage.getFetchType().isPresent()) handleSynchronizeFetchMessage(syncMessage.getFetchType().get()); - else if (syncMessage.getMessageRequestResponse().isPresent()) handleSynchronizeMessageRequestResponse(syncMessage.getMessageRequestResponse().get()); + else if (syncMessage.getFetchType().isPresent()) handleSynchronizeFetchMessage(syncMessage.getFetchType().get(), content.getTimestamp()); + else if (syncMessage.getMessageRequestResponse().isPresent()) handleSynchronizeMessageRequestResponse(syncMessage.getMessageRequestResponse().get(), content.getTimestamp()); else if (syncMessage.getOutgoingPaymentMessage().isPresent()) handleSynchronizeOutgoingPayment(content, syncMessage.getOutgoingPaymentMessage().get()); else warn(String.valueOf(content.getTimestamp()), "Contains no known sync types..."); } else if (content.getCallMessage().isPresent()) { @@ -383,6 +383,8 @@ public final class MessageContentProcessor { } private void handlePayment(@NonNull SignalServiceContent content, @NonNull SignalServiceDataMessage message, @NonNull Recipient senderRecipient) { + log(content.getTimestamp(), "Payment message."); + if (!message.getPayment().isPresent()) { throw new AssertionError(); } @@ -651,6 +653,8 @@ public final class MessageContentProcessor { @NonNull Optional groupId, @NonNull Recipient senderRecipient) { + log(content.getTimestamp(), "Group call update message."); + if (!groupId.isPresent() || !groupId.get().isV2()) { Log.w(TAG, "Invalid group for group call update message"); return; @@ -670,6 +674,8 @@ public final class MessageContentProcessor { @NonNull Optional smsMessageId, @NonNull Recipient senderRecipient) { + log(content.getTimestamp(), "End session message."); + MessageDatabase smsDatabase = SignalDatabase.sms(); IncomingTextMessage incomingTextMessage = new IncomingTextMessage(senderRecipient.getId(), content.getSenderDevice(), @@ -705,9 +711,11 @@ public final class MessageContentProcessor { } } - private long handleSynchronizeSentEndSessionMessage(@NonNull SentTranscriptMessage message) + private long handleSynchronizeSentEndSessionMessage(@NonNull SentTranscriptMessage message, long envelopeTimestamp) throws BadGroupIdException { + log(envelopeTimestamp, "Synchronize end session message."); + MessageDatabase database = SignalDatabase.sms(); Recipient recipient = getSyncMessageDestination(message); OutgoingTextMessage outgoingTextMessage = new OutgoingTextMessage(recipient, "", -1); @@ -741,6 +749,8 @@ public final class MessageContentProcessor { long receivedTime) throws StorageFailedException, BadGroupIdException { + log(content.getTimestamp(), "GroupV1 message."); + GroupV1MessageProcessor.process(context, content, message, false); if (message.getExpiresInSeconds() != 0 && message.getExpiresInSeconds() != threadRecipient.getExpiresInSeconds()) { @@ -757,6 +767,8 @@ public final class MessageContentProcessor { @NonNull Recipient senderRecipient) throws BadGroupIdException { + log(content.getTimestamp(), "Unknown group message."); + if (group.getGroupV1().isPresent()) { SignalServiceGroup groupV1 = group.getGroupV1().get(); if (groupV1.getType() != SignalServiceGroup.Type.REQUEST_INFO) { @@ -781,6 +793,8 @@ public final class MessageContentProcessor { long receivedTime) throws StorageFailedException { + log(content.getTimestamp(), "Expiration update."); + if (groupId.isPresent() && groupId.get().isV2()) { warn(String.valueOf(content.getTimestamp()), "Expiration update received for GV2. Ignoring."); return null; @@ -834,6 +848,8 @@ public final class MessageContentProcessor { } private @Nullable MessageId handleReaction(@NonNull SignalServiceContent content, @NonNull SignalServiceDataMessage message, @NonNull Recipient senderRecipient) { + log(content.getTimestamp(), "Handle reaction for message " + message.getReaction().get().getTargetSentTimestamp()); + SignalServiceDataMessage.Reaction reaction = message.getReaction().get(); if (!EmojiUtil.isEmoji(reaction.getEmoji())) { @@ -889,6 +905,8 @@ public final class MessageContentProcessor { } private @Nullable MessageId handleRemoteDelete(@NonNull SignalServiceContent content, @NonNull SignalServiceDataMessage message, @NonNull Recipient senderRecipient) { + log(content.getTimestamp(), "Remote delete for message " + message.getRemoteDelete().get().getTargetSentTimestamp()); + SignalServiceDataMessage.RemoteDelete delete = message.getRemoteDelete().get(); MessageRecord targetMessage = SignalDatabase.mmsSms().getMessageFor(delete.getTargetSentTimestamp(), senderRecipient.getId()); @@ -910,10 +928,13 @@ public final class MessageContentProcessor { } private void handleSynchronizeVerifiedMessage(@NonNull VerifiedMessage verifiedMessage) { + log(verifiedMessage.getTimestamp(), "Synchronize verified message."); IdentityUtil.processVerifiedMessage(context, verifiedMessage); } - private void handleSynchronizeStickerPackOperation(@NonNull List stickerPackOperations) { + private void handleSynchronizeStickerPackOperation(@NonNull List stickerPackOperations, long envelopeTimestamp) { + log(envelopeTimestamp, "Synchronize sticker pack operation."); + JobManager jobManager = ApplicationDependencies.getJobManager(); for (StickerPackOperationMessage operation : stickerPackOperations) { @@ -935,7 +956,9 @@ public final class MessageContentProcessor { } } - private void handleSynchronizeConfigurationMessage(@NonNull ConfigurationMessage configurationMessage) { + private void handleSynchronizeConfigurationMessage(@NonNull ConfigurationMessage configurationMessage, long envelopeTimestamp) { + log(envelopeTimestamp, "Synchronize configuration message."); + if (configurationMessage.getReadReceipts().isPresent()) { TextSecurePreferences.setReadReceiptsEnabled(context, configurationMessage.getReadReceipts().get()); } @@ -957,8 +980,8 @@ public final class MessageContentProcessor { SignalDatabase.recipients().applyBlockedUpdate(blockMessage.getAddresses(), blockMessage.getGroupIds()); } - private void handleSynchronizeFetchMessage(@NonNull SignalServiceSyncMessage.FetchType fetchType) { - log("Received fetch request with type: " + fetchType); + private void handleSynchronizeFetchMessage(@NonNull SignalServiceSyncMessage.FetchType fetchType, long envelopeTimestamp) { + log(envelopeTimestamp, "Received fetch request with type: " + fetchType); switch (fetchType) { case LOCAL_PROFILE: @@ -975,9 +998,11 @@ public final class MessageContentProcessor { } } - private void handleSynchronizeMessageRequestResponse(@NonNull MessageRequestResponseMessage response) + private void handleSynchronizeMessageRequestResponse(@NonNull MessageRequestResponseMessage response, long envelopeTimestamp) throws BadGroupIdException { + log(envelopeTimestamp, "Synchronize message request response."); + RecipientDatabase recipientDatabase = SignalDatabase.recipients(); ThreadDatabase threadDatabase = SignalDatabase.threads(); @@ -1075,9 +1100,9 @@ public final class MessageContentProcessor { long threadId = -1; if (message.isRecipientUpdate()) { - handleGroupRecipientUpdate(message); + handleGroupRecipientUpdate(message, content.getTimestamp()); } else if (message.getMessage().isEndSession()) { - threadId = handleSynchronizeSentEndSessionMessage(message); + threadId = handleSynchronizeSentEndSessionMessage(message, content.getTimestamp()); } else if (message.getMessage().isGroupV1Update()) { Long gv1ThreadId = GroupV1MessageProcessor.process(context, content, message.getMessage(), true); threadId = gv1ThreadId == null ? -1 : gv1ThreadId; @@ -1096,9 +1121,9 @@ public final class MessageContentProcessor { } else if (message.getMessage().getRemoteDelete().isPresent()) { handleRemoteDelete(content, message.getMessage(), senderRecipient); } else if (message.getMessage().getAttachments().isPresent() || message.getMessage().getQuote().isPresent() || message.getMessage().getPreviews().isPresent() || message.getMessage().getSticker().isPresent() || message.getMessage().isViewOnce() || message.getMessage().getMentions().isPresent()) { - threadId = handleSynchronizeSentMediaMessage(message); + threadId = handleSynchronizeSentMediaMessage(message, content.getTimestamp()); } else { - threadId = handleSynchronizeSentTextMessage(message); + threadId = handleSynchronizeSentTextMessage(message, content.getTimestamp()); } if (message.getMessage().getGroupContext().isPresent() && groupDatabase.isUnknownGroup(GroupUtil.idFromGroupContext(message.getMessage().getGroupContext().get()))) { @@ -1133,6 +1158,8 @@ public final class MessageContentProcessor { @NonNull SentTranscriptMessage message) throws IOException, GroupChangeBusyException { + log(content.getTimestamp(), "Synchronize sent GV2 update for message with timestamp " + message.getTimestamp()); + SignalServiceGroupV2 signalServiceGroupV2 = message.getMessage().getGroupContext().get().getGroupV2().get(); GroupId.V2 groupIdV2 = GroupId.v2(signalServiceGroupV2.getMasterKey()); @@ -1141,8 +1168,10 @@ public final class MessageContentProcessor { } } - private void handleSynchronizeRequestMessage(@NonNull RequestMessage message) + private void handleSynchronizeRequestMessage(@NonNull RequestMessage message, long envelopeTimestamp) { + log(envelopeTimestamp, "Synchronize request message."); + if (message.isContactsRequest()) { ApplicationDependencies.getJobManager().add(new MultiDeviceContactUpdateJob(true)); } @@ -1170,6 +1199,8 @@ public final class MessageContentProcessor { private void handleSynchronizeReadMessage(@NonNull List readMessages, long envelopeTimestamp, @NonNull Recipient senderRecipient) { + log(envelopeTimestamp, "Synchronize read message."); + Map threadToLatestRead = new HashMap<>(); for (ReadMessage readMessage : readMessages) { List> expiringText = SignalDatabase.sms().setTimestampRead(new SyncMessageId(senderRecipient.getId(), readMessage.getTimestamp()), @@ -1203,6 +1234,8 @@ public final class MessageContentProcessor { } private void handleSynchronizeViewedMessage(@NonNull List viewedMessages, long envelopeTimestamp) { + log(envelopeTimestamp, "Synchronize viewed message."); + List toMarkViewed = Stream.of(viewedMessages) .map(message -> { RecipientId author = Recipient.externalPush(context, message.getSender()).getId(); @@ -1221,7 +1254,7 @@ public final class MessageContentProcessor { } private void handleSynchronizeViewOnceOpenMessage(@NonNull ViewOnceOpenMessage openMessage, long envelopeTimestamp) { - log(String.valueOf(envelopeTimestamp), "Handling a view-once open for message: " + openMessage.getTimestamp()); + log(envelopeTimestamp, "Handling a view-once open for message: " + openMessage.getTimestamp()); RecipientId author = Recipient.externalPush(context, openMessage.getSender()).getId(); long timestamp = openMessage.getTimestamp(); @@ -1247,6 +1280,8 @@ public final class MessageContentProcessor { long receivedTime) throws StorageFailedException { + log(message.getTimestamp(), "Media message."); + notifyTypingStoppedFromIncomingMessage(senderRecipient, threadRecipient, content.getSenderDevice()); Optional insertResult; @@ -1322,6 +1357,8 @@ public final class MessageContentProcessor { private long handleSynchronizeSentExpirationUpdate(@NonNull SentTranscriptMessage message) throws MmsException, BadGroupIdException { + log(message.getTimestamp(), "Synchronize sent expiration update."); + MessageDatabase database = SignalDatabase.mms(); Recipient recipient = getSyncMessageDestination(message); @@ -1339,9 +1376,11 @@ public final class MessageContentProcessor { return threadId; } - private long handleSynchronizeSentMediaMessage(@NonNull SentTranscriptMessage message) + private long handleSynchronizeSentMediaMessage(@NonNull SentTranscriptMessage message, long envelopeTimestamp) throws MmsException, BadGroupIdException { + log(envelopeTimestamp, "Synchronize sent media message for " + message.getTimestamp()); + MessageDatabase database = SignalDatabase.mms(); Recipient recipients = getSyncMessageDestination(message); Optional quote = getValidatedQuote(message.getMessage().getQuote()); @@ -1426,9 +1465,11 @@ public final class MessageContentProcessor { return threadId; } - private void handleGroupRecipientUpdate(@NonNull SentTranscriptMessage message) + private void handleGroupRecipientUpdate(@NonNull SentTranscriptMessage message, long envelopeTimestamp) throws BadGroupIdException { + log(envelopeTimestamp, "Group recipient update."); + Recipient recipient = getSyncMessageDestination(message); if (!recipient.isGroup()) { @@ -1483,6 +1524,7 @@ public final class MessageContentProcessor { long receivedTime) throws StorageFailedException { + log(message.getTimestamp(), "Text message."); MessageDatabase database = SignalDatabase.sms(); String body = message.getBody().isPresent() ? message.getBody().get() : ""; @@ -1522,9 +1564,11 @@ public final class MessageContentProcessor { } } - private long handleSynchronizeSentTextMessage(@NonNull SentTranscriptMessage message) + private long handleSynchronizeSentTextMessage(@NonNull SentTranscriptMessage message, long envelopeTimestamp) throws MmsException, BadGroupIdException { + log(envelopeTimestamp, "Synchronize sent text message for " + message.getTimestamp()); + Recipient recipient = getSyncMessageDestination(message); String body = message.getMessage().getBody().or(""); long expiresInMillis = TimeUnit.SECONDS.toMillis(message.getMessage().getExpiresInSeconds()); @@ -1587,6 +1631,8 @@ public final class MessageContentProcessor { private void handleInvalidVersionMessage(@NonNull String sender, int senderDevice, long timestamp, @NonNull Optional smsMessageId) { + log(timestamp, "Invalid version message."); + MessageDatabase smsDatabase = SignalDatabase.sms(); if (!smsMessageId.isPresent()) { @@ -1604,6 +1650,8 @@ public final class MessageContentProcessor { private void handleCorruptMessage(@NonNull String sender, int senderDevice, long timestamp, @NonNull Optional smsMessageId) { + log(timestamp, "Corrupt message."); + MessageDatabase smsDatabase = SignalDatabase.sms(); if (!smsMessageId.isPresent()) { @@ -1624,6 +1672,8 @@ public final class MessageContentProcessor { long timestamp, @NonNull Optional smsMessageId) { + log(timestamp, "Unsupported data message."); + MessageDatabase smsDatabase = SignalDatabase.sms(); if (!smsMessageId.isPresent()) { @@ -1644,6 +1694,8 @@ public final class MessageContentProcessor { long timestamp, @NonNull Optional smsMessageId) { + log(timestamp, "Invalid message."); + MessageDatabase smsDatabase = SignalDatabase.sms(); if (!smsMessageId.isPresent()) { @@ -1661,6 +1713,8 @@ public final class MessageContentProcessor { private void handleLegacyMessage(@NonNull String sender, int senderDevice, long timestamp, @NonNull Optional smsMessageId) { + log(timestamp, "Legacy message."); + MessageDatabase smsDatabase = SignalDatabase.sms(); if (!smsMessageId.isPresent()) { @@ -1679,6 +1733,8 @@ public final class MessageContentProcessor { @NonNull byte[] messageProfileKeyBytes, @NonNull Recipient senderRecipient) { + log(content.getTimestamp(), "Profile key."); + RecipientDatabase database = SignalDatabase.recipients(); ProfileKey messageProfileKey = ProfileKeyUtil.profileKeyOrNull(messageProfileKeyBytes);