Log sent timestamp with message sends.

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);
   }
 }

app/src/main/java/org/thoughtcrime/securesms/jobs/PushDecryptMessageJob.java

@@ -151,6 +151,7 @@ public final class PushDecryptMessageJob extends BaseJob {
   }
 
   private @NonNull List<Job> 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)));

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);
     }

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);
     }
   }

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();

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<byte[]>                 profileKey         = getProfileKey(messageRecipient);
       Optional<UnidentifiedAccessPair> 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())

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, String.valueOf(message.getDateSent()), "Recipient: " + recipient);
-      log(TAG, "Message Parts: " + messages.size());
+      log(TAG, String.valueOf(message.getDateSent()), "Message Parts: " + messages.size());
 
       try {
         for (int i=0;i<messages.size();i++) {