From 12dfcaf7e79a300e962671a97df6e8bbfd368531 Mon Sep 17 00:00:00 2001 From: Greyson Parrelli Date: Wed, 2 Sep 2020 13:13:03 -0400 Subject: [PATCH] Log sent timestamp with message sends. --- .../thoughtcrime/securesms/jobs/BaseJob.java | 18 +++++++++++++++--- .../securesms/jobs/PushDecryptMessageJob.java | 1 + .../securesms/jobs/PushGroupSendJob.java | 6 +++--- .../securesms/jobs/PushMediaSendJob.java | 18 +++++++++--------- .../securesms/jobs/PushProcessMessageJob.java | 2 ++ .../securesms/jobs/PushTextSendJob.java | 18 +++++++++--------- .../securesms/jobs/SmsSendJob.java | 8 ++++---- 7 files changed, 43 insertions(+), 28 deletions(-) diff --git a/app/src/main/java/org/thoughtcrime/securesms/jobs/BaseJob.java b/app/src/main/java/org/thoughtcrime/securesms/jobs/BaseJob.java index b84e92e97..f22115973 100644 --- a/app/src/main/java/org/thoughtcrime/securesms/jobs/BaseJob.java +++ b/app/src/main/java/org/thoughtcrime/securesms/jobs/BaseJob.java @@ -51,11 +51,19 @@ public abstract class BaseJob extends Job { } protected void log(@NonNull String tag, @NonNull String message) { - Log.i(tag, JobLogger.format(this, message)); + log(tag, "", JobLogger.format(this, message)); + } + + protected void log(@NonNull String tag, @NonNull String extra, @NonNull String message) { + Log.i(tag, JobLogger.format(this, extra, message)); } protected void warn(@NonNull String tag, @NonNull String message) { - warn(tag, message, null); + warn(tag, "", message, null); + } + + protected void warn(@NonNull String tag, @NonNull String event, @NonNull String message) { + warn(tag, event, message, null); } protected void warn(@NonNull String tag, @Nullable Throwable t) { @@ -63,6 +71,10 @@ public abstract class BaseJob extends Job { } protected void warn(@NonNull String tag, @NonNull String message, @Nullable Throwable t) { - Log.w(tag, JobLogger.format(this, message), t); + warn(tag, "", message, t); + } + + protected void warn(@NonNull String tag, @NonNull String extra, @NonNull String message, @Nullable Throwable t) { + Log.w(tag, JobLogger.format(this, extra, message), t); } } diff --git a/app/src/main/java/org/thoughtcrime/securesms/jobs/PushDecryptMessageJob.java b/app/src/main/java/org/thoughtcrime/securesms/jobs/PushDecryptMessageJob.java index 92f798c11..2ebb3e4bb 100644 --- a/app/src/main/java/org/thoughtcrime/securesms/jobs/PushDecryptMessageJob.java +++ b/app/src/main/java/org/thoughtcrime/securesms/jobs/PushDecryptMessageJob.java @@ -151,6 +151,7 @@ public final class PushDecryptMessageJob extends BaseJob { } private @NonNull List handleMessage(@NonNull SignalServiceEnvelope envelope) throws NoSenderException { + Log.i(TAG, "Processing message ID " + envelope.getTimestamp()); try { SignalProtocolStore axolotlStore = new SignalProtocolStoreImpl(context); SignalServiceAddress localAddress = new SignalServiceAddress(Optional.of(TextSecurePreferences.getLocalUuid(context)), Optional.of(TextSecurePreferences.getLocalNumber(context))); diff --git a/app/src/main/java/org/thoughtcrime/securesms/jobs/PushGroupSendJob.java b/app/src/main/java/org/thoughtcrime/securesms/jobs/PushGroupSendJob.java index fd5ed5644..0d4f2789d 100644 --- a/app/src/main/java/org/thoughtcrime/securesms/jobs/PushGroupSendJob.java +++ b/app/src/main/java/org/thoughtcrime/securesms/jobs/PushGroupSendJob.java @@ -162,7 +162,7 @@ public final class PushGroupSendJob extends PushSendJob { ApplicationDependencies.getJobManager().cancelAllInQueue(TypingSendJob.getQueue(threadId)); if (database.isSent(messageId)) { - log(TAG, "Message " + messageId + " was already sent. Ignoring."); + log(TAG, String.valueOf(message.getSentTimeMillis()), "Message " + messageId + " was already sent. Ignoring."); return; } @@ -173,7 +173,7 @@ public final class PushGroupSendJob extends PushSendJob { } try { - log(TAG, "Sending message: " + messageId); + log(TAG, String.valueOf(message.getSentTimeMillis()), "Sending message: " + messageId); if (!groupRecipient.resolve().isProfileSharing() && !database.isGroupQuitMessage(messageId)) { RecipientUtil.shareProfileIfFirstSecureMessage(context, groupRecipient); @@ -253,7 +253,7 @@ public final class PushGroupSendJob extends PushSendJob { RetrieveProfileJob.enqueue(mismatchRecipientIds); } } catch (UntrustedIdentityException | UndeliverableMessageException e) { - warn(TAG, e); + warn(TAG, String.valueOf(message.getSentTimeMillis()), e); database.markAsSentFailed(messageId); notifyMediaMessageDeliveryFailed(context, messageId); } diff --git a/app/src/main/java/org/thoughtcrime/securesms/jobs/PushMediaSendJob.java b/app/src/main/java/org/thoughtcrime/securesms/jobs/PushMediaSendJob.java index 10c372af0..d1a199075 100644 --- a/app/src/main/java/org/thoughtcrime/securesms/jobs/PushMediaSendJob.java +++ b/app/src/main/java/org/thoughtcrime/securesms/jobs/PushMediaSendJob.java @@ -113,12 +113,12 @@ public class PushMediaSendJob extends PushSendJob { OutgoingMediaMessage message = database.getOutgoingMessage(messageId); if (database.isSent(messageId)) { - warn(TAG, "Message " + messageId + " was already sent. Ignoring."); + warn(TAG, String.valueOf(message.getSentTimeMillis()), "Message " + messageId + " was already sent. Ignoring."); return; } try { - log(TAG, "Sending message: " + messageId); + log(TAG, String.valueOf(message.getSentTimeMillis()), "Sending message: " + messageId); RecipientUtil.shareProfileIfFirstSecureMessage(context, message.getRecipient()); @@ -139,13 +139,13 @@ public class PushMediaSendJob extends PushSendJob { } if (unidentified && accessMode == UnidentifiedAccessMode.UNKNOWN && profileKey == null) { - log(TAG, "Marking recipient as UD-unrestricted following a UD send."); + log(TAG, String.valueOf(message.getSentTimeMillis()), "Marking recipient as UD-unrestricted following a UD send."); DatabaseFactory.getRecipientDatabase(context).setUnidentifiedAccessMode(recipient.getId(), UnidentifiedAccessMode.UNRESTRICTED); } else if (unidentified && accessMode == UnidentifiedAccessMode.UNKNOWN) { - log(TAG, "Marking recipient as UD-enabled following a UD send."); + log(TAG, String.valueOf(message.getSentTimeMillis()), "Marking recipient as UD-enabled following a UD send."); DatabaseFactory.getRecipientDatabase(context).setUnidentifiedAccessMode(recipient.getId(), UnidentifiedAccessMode.ENABLED); } else if (!unidentified && accessMode != UnidentifiedAccessMode.DISABLED) { - log(TAG, "Marking recipient as UD-disabled following a non-UD send."); + log(TAG, String.valueOf(message.getSentTimeMillis()), "Marking recipient as UD-disabled following a non-UD send."); DatabaseFactory.getRecipientDatabase(context).setUnidentifiedAccessMode(recipient.getId(), UnidentifiedAccessMode.DISABLED); } @@ -158,7 +158,7 @@ public class PushMediaSendJob extends PushSendJob { DatabaseFactory.getAttachmentDatabase(context).deleteAttachmentFilesForViewOnceMessage(messageId); } - log(TAG, "Sent message: " + messageId); + log(TAG, String.valueOf(message.getSentTimeMillis()), "Sent message: " + messageId); } catch (InsecureFallbackApprovalException ifae) { warn(TAG, "Failure", ifae); @@ -231,13 +231,13 @@ public class PushMediaSendJob extends PushSendJob { return messageSender.sendMessage(address, UnidentifiedAccessUtil.getAccessFor(context, messageRecipient), mediaMessage).getSuccess().isUnidentified(); } } catch (UnregisteredUserException e) { - warn(TAG, e); + warn(TAG, String.valueOf(message.getSentTimeMillis()), e); throw new InsecureFallbackApprovalException(e); } catch (FileNotFoundException e) { - warn(TAG, e); + warn(TAG, String.valueOf(message.getSentTimeMillis()), e); throw new UndeliverableMessageException(e); } catch (IOException e) { - warn(TAG, e); + warn(TAG, String.valueOf(message.getSentTimeMillis()), e); throw new RetryLaterException(e); } } diff --git a/app/src/main/java/org/thoughtcrime/securesms/jobs/PushProcessMessageJob.java b/app/src/main/java/org/thoughtcrime/securesms/jobs/PushProcessMessageJob.java index ff30e80d3..1f5c8f8a5 100644 --- a/app/src/main/java/org/thoughtcrime/securesms/jobs/PushProcessMessageJob.java +++ b/app/src/main/java/org/thoughtcrime/securesms/jobs/PushProcessMessageJob.java @@ -338,6 +338,8 @@ public final class PushProcessMessageJob extends BaseJob { return; } + Log.i(TAG, "Processing message ID " + content.getTimestamp()); + if (content.getDataMessage().isPresent()) { SignalServiceDataMessage message = content.getDataMessage().get(); boolean isMediaMessage = message.getAttachments().isPresent() || message.getQuote().isPresent() || message.getSharedContacts().isPresent() || message.getPreviews().isPresent() || message.getSticker().isPresent() || message.getMentions().isPresent(); diff --git a/app/src/main/java/org/thoughtcrime/securesms/jobs/PushTextSendJob.java b/app/src/main/java/org/thoughtcrime/securesms/jobs/PushTextSendJob.java index 18cbbea57..fb2104552 100644 --- a/app/src/main/java/org/thoughtcrime/securesms/jobs/PushTextSendJob.java +++ b/app/src/main/java/org/thoughtcrime/securesms/jobs/PushTextSendJob.java @@ -76,12 +76,12 @@ public class PushTextSendJob extends PushSendJob { SmsMessageRecord record = database.getSmsMessage(messageId); if (!record.isPending() && !record.isFailed()) { - warn(TAG, "Message " + messageId + " was already sent. Ignoring."); + warn(TAG, String.valueOf(record.getDateSent()), "Message " + messageId + " was already sent. Ignoring."); return; } try { - log(TAG, "Sending message: " + messageId); + log(TAG, String.valueOf(record.getDateSent()), "Sending message: " + messageId); RecipientUtil.shareProfileIfFirstSecureMessage(context, record.getRecipient()); @@ -101,13 +101,13 @@ public class PushTextSendJob extends PushSendJob { } if (unidentified && accessMode == UnidentifiedAccessMode.UNKNOWN && profileKey == null) { - log(TAG, "Marking recipient as UD-unrestricted following a UD send."); + log(TAG, String.valueOf(record.getDateSent()), "Marking recipient as UD-unrestricted following a UD send."); DatabaseFactory.getRecipientDatabase(context).setUnidentifiedAccessMode(recipient.getId(), UnidentifiedAccessMode.UNRESTRICTED); } else if (unidentified && accessMode == UnidentifiedAccessMode.UNKNOWN) { - log(TAG, "Marking recipient as UD-enabled following a UD send."); + log(TAG, String.valueOf(record.getDateSent()), "Marking recipient as UD-enabled following a UD send."); DatabaseFactory.getRecipientDatabase(context).setUnidentifiedAccessMode(recipient.getId(), UnidentifiedAccessMode.ENABLED); } else if (!unidentified && accessMode != UnidentifiedAccessMode.DISABLED) { - log(TAG, "Marking recipient as UD-disabled following a non-UD send."); + log(TAG, String.valueOf(record.getDateSent()), "Marking recipient as UD-disabled following a non-UD send."); DatabaseFactory.getRecipientDatabase(context).setUnidentifiedAccessMode(recipient.getId(), UnidentifiedAccessMode.DISABLED); } @@ -116,15 +116,15 @@ public class PushTextSendJob extends PushSendJob { expirationManager.scheduleDeletion(record.getId(), record.isMms(), record.getExpiresIn()); } - log(TAG, "Sent message: " + messageId); + log(TAG, String.valueOf(record.getDateSent()), "Sent message: " + messageId); } catch (InsecureFallbackApprovalException e) { - warn(TAG, "Failure", e); + warn(TAG, String.valueOf(record.getDateSent()), "Failure", e); database.markAsPendingInsecureSmsFallback(record.getId()); ApplicationDependencies.getMessageNotifier().notifyMessageDeliveryFailed(context, record.getRecipient(), record.getThreadId()); ApplicationDependencies.getJobManager().add(new DirectoryRefreshJob(false)); } catch (UntrustedIdentityException e) { - warn(TAG, "Failure", e); + warn(TAG, String.valueOf(record.getDateSent()), "Failure", e); RecipientId recipientId = Recipient.external(context, e.getIdentifier()).getId(); database.addMismatchedIdentity(record.getId(), recipientId, e.getIdentityKey()); database.markAsSentFailed(record.getId()); @@ -164,7 +164,7 @@ public class PushTextSendJob extends PushSendJob { Optional profileKey = getProfileKey(messageRecipient); Optional unidentifiedAccess = UnidentifiedAccessUtil.getAccessFor(context, messageRecipient); - log(TAG, "Have access key to use: " + unidentifiedAccess.isPresent()); + log(TAG, String.valueOf(message.getDateSent()), "Have access key to use: " + unidentifiedAccess.isPresent()); SignalServiceDataMessage textSecureMessage = SignalServiceDataMessage.newBuilder() .withTimestamp(message.getDateSent()) diff --git a/app/src/main/java/org/thoughtcrime/securesms/jobs/SmsSendJob.java b/app/src/main/java/org/thoughtcrime/securesms/jobs/SmsSendJob.java index 353bb216d..1aa932063 100644 --- a/app/src/main/java/org/thoughtcrime/securesms/jobs/SmsSendJob.java +++ b/app/src/main/java/org/thoughtcrime/securesms/jobs/SmsSendJob.java @@ -88,9 +88,9 @@ public class SmsSendJob extends SendJob { } try { - log(TAG, "Sending message: " + messageId + " (attempt " + runAttempt + ")"); + log(TAG, String.valueOf(record.getDateSent()), "Sending message: " + messageId + " (attempt " + runAttempt + ")"); deliver(record); - log(TAG, "Sent message: " + messageId); + log(TAG, String.valueOf(record.getDateSent()), "Sent message: " + messageId); } catch (UndeliverableMessageException ude) { warn(TAG, ude); DatabaseFactory.getSmsDatabase(context).markAsSentFailed(record.getId()); @@ -149,8 +149,8 @@ public class SmsSendJob extends SendJob { getSmsManagerFor(message.getSubscriptionId()).sendMultipartTextMessage(recipient, null, messages, sentIntents, deliveredIntents); } catch (NullPointerException | IllegalArgumentException npe) { warn(TAG, npe); - log(TAG, "Recipient: " + recipient); - log(TAG, "Message Parts: " + messages.size()); + log(TAG, String.valueOf(message.getDateSent()), "Recipient: " + recipient); + log(TAG, String.valueOf(message.getDateSent()), "Message Parts: " + messages.size()); try { for (int i=0;i