Improve debug logging for reconciliation.

2026-02-23 11:15:44 +00:00 · 2025-09-12 12:02:04 -04:00
parent c19017f037
commit 9021883baa
5 changed files with 124 additions and 61 deletions
--- a/app/src/main/java/org/thoughtcrime/securesms/database/AttachmentTable.kt
+++ b/app/src/main/java/org/thoughtcrime/securesms/database/AttachmentTable.kt
@@ -132,6 +132,7 @@ import java.security.NoSuchAlgorithmException
 import java.util.LinkedList
 import java.util.Optional
 import java.util.UUID
+import kotlin.text.appendLine
 import kotlin.time.Duration
 import kotlin.time.Duration.Companion.days
 import kotlin.time.Duration.Companion.milliseconds
@@ -3180,27 +3181,31 @@ class AttachmentTable(
    val byteStringMediaIds: Set<ByteString> = mediaIds.map { it.value.toByteString() }.toSet()
    val found = mutableListOf<Pair<DatabaseAttachment, Boolean>>()

-    readableDatabase
-      .select(*PROJECTION)
-      .from(TABLE_NAME)
-      .where("$REMOTE_KEY NOT NULL AND $DATA_HASH_END NOT NULL")
-      .run()
-      .forEach { cursor ->
-        val remoteKey = Base64.decode(cursor.requireNonNullString(REMOTE_KEY))
-        val plaintextHash = Base64.decode(cursor.requireNonNullString(DATA_HASH_END))
-        val mediaId = MediaName.fromPlaintextHashAndRemoteKey(plaintextHash, remoteKey).toMediaId(SignalStore.backup.mediaRootBackupKey).value.toByteString()
-        val mediaIdThumbnail = MediaName.fromPlaintextHashAndRemoteKeyForThumbnail(plaintextHash, remoteKey).toMediaId(SignalStore.backup.mediaRootBackupKey).value.toByteString()
+    run {
+      readableDatabase
+        .select(*PROJECTION)
+        .from(TABLE_NAME)
+        .where("$REMOTE_KEY NOT NULL AND $DATA_HASH_END NOT NULL")
+        .groupBy(DATA_HASH_END)
+        .run()
+        .forEach { cursor ->

-        if (mediaId in byteStringMediaIds) {
-          found.add(getAttachment(cursor) to false)
+          val remoteKey = Base64.decode(cursor.requireNonNullString(REMOTE_KEY))
+          val plaintextHash = Base64.decode(cursor.requireNonNullString(DATA_HASH_END))
+          val mediaId = MediaName.fromPlaintextHashAndRemoteKey(plaintextHash, remoteKey).toMediaId(SignalStore.backup.mediaRootBackupKey).value.toByteString()
+          val mediaIdThumbnail = MediaName.fromPlaintextHashAndRemoteKeyForThumbnail(plaintextHash, remoteKey).toMediaId(SignalStore.backup.mediaRootBackupKey).value.toByteString()
+
+          if (mediaId in byteStringMediaIds) {
+            found.add(getAttachment(cursor) to false)
+          }
+
+          if (mediaIdThumbnail in byteStringMediaIds) {
+            found.add(getAttachment(cursor) to true)
+          }
+
+          if (found.size >= limit) return@run
        }
-
-        if (mediaIdThumbnail in byteStringMediaIds) {
-          found.add(getAttachment(cursor) to true)
-        }
-
-        if (found.size >= limit) return@forEach
-      }
+    }

    return found
  }
@@ -3710,6 +3715,60 @@ class AttachmentTable(

    val totalUploadCount get() = uploadedAttachmentCount + uploadedThumbnailCount
    val totalUploadBytes get() = uploadedAttachmentBytes + uploadedThumbnailBytes
+
+    fun prettyString(): String {
+      return buildString {
+        appendLine("Total attachment rows: $totalAttachmentRows")
+        appendLine("Total eligible for upload rows: $totalEligibleForUploadRows")
+        appendLine("Total unique media names eligible for upload: $totalUniqueMediaNamesEligibleForUpload")
+        appendLine("Total unique data files: $totalUniqueDataFiles")
+        appendLine("Total unique media names: $totalUniqueMediaNames")
+        appendLine("Media names with thumbnails count: $mediaNamesWithThumbnailsCount")
+        appendLine("Pending attachment upload bytes: $pendingAttachmentUploadBytes")
+        appendLine("Uploaded attachment bytes: $uploadedAttachmentBytes")
+        appendLine("Uploaded thumbnail bytes: $uploadedThumbnailBytes")
+        appendLine("Total upload count: $totalUploadCount")
+        appendLine("Total upload bytes: $totalUploadBytes")
+
+        if (archiveStatusMediaNameCounts.isNotEmpty()) {
+          appendLine("Archive status media name counts:")
+          archiveStatusMediaNameCounts.forEach { (state, count) ->
+            appendLine("  ${state.name}: $count")
+          }
+        }
+
+        if (archiveStatusMediaNameThumbnailCounts.isNotEmpty()) {
+          appendLine("Archive status media name thumbnail counts:")
+          archiveStatusMediaNameThumbnailCounts.forEach { (state, count) ->
+            appendLine("  ${state.name}: $count")
+          }
+        }
+      }
+    }
+
+    fun shortPrettyString(): String {
+      return buildString {
+        appendLine("Total eligible for upload rows: $totalEligibleForUploadRows")
+        appendLine("Total unique media names eligible for upload: $totalUniqueMediaNamesEligibleForUpload")
+        appendLine("Total unique data files: $totalUniqueDataFiles")
+        appendLine("Total unique media names: $totalUniqueMediaNames")
+        appendLine("Pending attachment upload bytes: $pendingAttachmentUploadBytes")
+
+        if (archiveStatusMediaNameCounts.isNotEmpty()) {
+          appendLine("Archive status media name counts:")
+          archiveStatusMediaNameCounts.forEach { (state, count) ->
+            appendLine("  ${state.name}: $count")
+          }
+        }
+
+        if (archiveStatusMediaNameThumbnailCounts.isNotEmpty()) {
+          appendLine("Archive status media name thumbnail counts:")
+          archiveStatusMediaNameThumbnailCounts.forEach { (state, count) ->
+            appendLine("  ${state.name}: $count")
+          }
+        }
+      }
+    }
  }

  data class CreateRemoteKeyResult(val totalCount: Int, val notQuoteOrSickerDupeNotFoundCount: Int, val notQuoteOrSickerDupeFoundCount: Int) {
--- a/app/src/main/java/org/thoughtcrime/securesms/jobs/ArchiveAttachmentReconciliationJob.kt
+++ b/app/src/main/java/org/thoughtcrime/securesms/jobs/ArchiveAttachmentReconciliationJob.kt
@@ -149,6 +149,8 @@ class ArchiveAttachmentReconciliationJob private constructor(
      return Result.failure()
    }

+    Log.d(TAG, "BEFORE:\n" + SignalDatabase.attachments.debugGetAttachmentStats().prettyString())
+
    val mediaObjectsThatMayNeedReUpload = SignalDatabase.backupMediaSnapshots.getMediaObjectsLastSeenOnCdnBeforeSnapshotVersion(snapshotVersion)
    val mayNeedReUploadCount = mediaObjectsThatMayNeedReUpload.count

@@ -198,14 +200,22 @@ class ArchiveAttachmentReconciliationJob private constructor(
        Log.i(TAG, "None of the $mayNeedReUploadCount CDN mismatches were bookkeeping errors.", true)
      }

+      Log.d(TAG, "AFTER:\n" + SignalDatabase.attachments.debugGetAttachmentStats().prettyString())
+
      if (internalUser && mediaIdsThatNeedUpload.isNotEmpty()) {
        Log.w(TAG, "Starting internal-only lookup of matching attachments. May take a while!")

-        val matchingAttachments = SignalDatabase.attachments.debugGetAttachmentsForMediaIds(mediaIdsThatNeedUpload, limit = 100)
-        Log.w(TAG, "Found ${matchingAttachments.size} out of the ${mediaIdsThatNeedUpload.size} attachments we looked up (capped lookups to 100).", true)
+        val matchingAttachments = SignalDatabase.attachments.debugGetAttachmentsForMediaIds(mediaIdsThatNeedUpload, limit = 10_000)
+        Log.w(TAG, "Found ${matchingAttachments.size} out of the ${mediaIdsThatNeedUpload.size} attachments we looked up (capped lookups to 10k).", true)

-        matchingAttachments.forEach { attachment ->
-          Log.w(TAG, "Needed Upload: attachmentId=${attachment.first.attachmentId}, messageId=${attachment.first.mmsId}, thumbnail=${attachment.second}, contentType=${attachment.first.contentType}, quote=${attachment.first.quote}, transferState=${attachment.first.transferState}, archiveTransferState=${attachment.first.archiveTransferState}, hasData=${attachment.first.hasData}")
+        matchingAttachments.forEach { pair ->
+          val (attachment, isThumbnail) = pair
+          if (isThumbnail) {
+            val thumbnailTransferState = SignalDatabase.attachments.getArchiveThumbnailTransferState(attachment.attachmentId)
+            Log.w(TAG, "[Thumbnail] Needed Upload: attachmentId=${attachment.attachmentId}, messageId=${attachment.mmsId}, contentType=${attachment.contentType}, quote=${attachment.quote}, transferState=${attachment.transferState}, archiveTransferState=${attachment.archiveTransferState}, archiveThumbnailTransferState=$thumbnailTransferState, hasData=${attachment.hasData}")
+          } else {
+            Log.w(TAG, "[Fullsize] Needed Upload: attachmentId=${attachment.attachmentId}, messageId=${attachment.mmsId}, contentType=${attachment.contentType}, quote=${attachment.quote}, transferState=${attachment.transferState}, archiveTransferState=${attachment.archiveTransferState}, hasData=${attachment.hasData}")
+          }
        }
      }

--- a/app/src/main/java/org/thoughtcrime/securesms/jobs/ArchiveCommitAttachmentDeletesJob.kt
+++ b/app/src/main/java/org/thoughtcrime/securesms/jobs/ArchiveCommitAttachmentDeletesJob.kt
@@ -40,13 +40,13 @@ class ArchiveCommitAttachmentDeletesJob private constructor(parameters: Paramete
    fun deleteMediaObjectsFromCdn(tag: String, attachmentsToDelete: Set<ArchivedMediaObject>, backoffGenerator: () -> Long, cancellationSignal: () -> Boolean): Result? {
      attachmentsToDelete.chunked(REMOTE_DELETE_BATCH_SIZE).forEach { chunk ->
        if (cancellationSignal()) {
-          Log.w(tag, "Job cancelled while deleting attachments from the CDN.")
+          Log.w(tag, "Job cancelled while deleting attachments from the CDN.", true)
          return Result.failure()
        }

        when (val result = BackupRepository.deleteAbandonedMediaObjects(chunk)) {
          is NetworkResult.Success -> {
-            Log.i(tag, "Successfully deleted ${chunk.size} attachments off of the CDN. (Note: Count includes thumbnails)")
+            Log.i(tag, "Successfully deleted ${chunk.size} attachments off of the CDN. (Note: Count includes thumbnails)", true)
          }

          is NetworkResult.NetworkError -> {
@@ -56,24 +56,24 @@ class ArchiveCommitAttachmentDeletesJob private constructor(parameters: Paramete
          is NetworkResult.StatusCodeError -> {
            when (result.code) {
              429 -> {
-                Log.w(tag, "Rate limited while attempting to delete media objects. Retrying later.")
+                Log.w(tag, "Rate limited while attempting to delete media objects. Retrying later.", true)
                return Result.retry(result.retryAfter()?.inWholeMilliseconds ?: backoffGenerator())
              }

              in 500..599 -> {
-                Log.w(tag, "Failed to delete attachments from CDN with code: ${result.code}. Retrying with a larger backoff.", result.getCause())
+                Log.w(tag, "Failed to delete attachments from CDN with code: ${result.code}. Retrying with a larger backoff.", result.getCause(), true)
                return Result.retry(1.hours.inWholeMilliseconds)
              }

              else -> {
-                Log.w(tag, "Failed to delete attachments from CDN with code: ${result.code}. Considering this a terminal failure.", result.getCause())
+                Log.w(tag, "Failed to delete attachments from CDN with code: ${result.code}. Considering this a terminal failure.", result.getCause(), true)
                return Result.failure()
              }
            }
          }

          is NetworkResult.ApplicationError -> {
-            Log.w(tag, "Crash when trying to delete attachments from the CDN", result.getCause())
+            Log.w(tag, "Crash when trying to delete attachments from the CDN", result.getCause(), true)
            Result.fatalFailure(RuntimeException(result.getCause()))
          }
        }
--- a/app/src/main/java/org/thoughtcrime/securesms/logsubmit/LogSectionRemoteBackups.kt
+++ b/app/src/main/java/org/thoughtcrime/securesms/logsubmit/LogSectionRemoteBackups.kt
@@ -11,7 +11,6 @@ import org.signal.donations.InAppPaymentType
 import org.thoughtcrime.securesms.backup.v2.ArchiveRestoreProgress
 import org.thoughtcrime.securesms.components.settings.app.subscription.DonationSerializationHelper.toFiatMoney
 import org.thoughtcrime.securesms.components.settings.app.subscription.InAppPaymentsRepository
-import org.thoughtcrime.securesms.database.AttachmentTable
 import org.thoughtcrime.securesms.database.SignalDatabase
 import org.thoughtcrime.securesms.database.model.InAppPaymentSubscriberRecord
 import org.thoughtcrime.securesms.dependencies.AppDependencies
@@ -94,42 +93,12 @@ class LogSectionRemoteBackups : LogSection {
    }

    output.append("\n -- Attachment Stats\n")
-    output.append(SignalDatabase.attachments.debugGetAttachmentStats().toPrettyString())
+    output.append(SignalDatabase.attachments.debugGetAttachmentStats().prettyString())

    return output
  }
 }

-private fun AttachmentTable.DebugAttachmentStats.toPrettyString(): String {
-  return buildString {
-    appendLine("Total attachment rows: $totalAttachmentRows")
-    appendLine("Total eligible for upload rows: $totalEligibleForUploadRows")
-    appendLine("Total unique media names eligible for upload: $totalUniqueMediaNamesEligibleForUpload")
-    appendLine("Total unique data files: $totalUniqueDataFiles")
-    appendLine("Total unique media names: $totalUniqueMediaNames")
-    appendLine("Media names with thumbnails count: $mediaNamesWithThumbnailsCount")
-    appendLine("Pending attachment upload bytes: $pendingAttachmentUploadBytes")
-    appendLine("Uploaded attachment bytes: $uploadedAttachmentBytes")
-    appendLine("Uploaded thumbnail bytes: $uploadedThumbnailBytes")
-    appendLine("Total upload count: $totalUploadCount")
-    appendLine("Total upload bytes: $totalUploadBytes")
-
-    if (archiveStatusMediaNameCounts.isNotEmpty()) {
-      appendLine("Archive status media name counts:")
-      archiveStatusMediaNameCounts.forEach { (state, count) ->
-        appendLine("  ${state.name}: $count")
-      }
-    }
-
-    if (archiveStatusMediaNameThumbnailCounts.isNotEmpty()) {
-      appendLine("Archive status media name thumbnail counts:")
-      archiveStatusMediaNameThumbnailCounts.forEach { (state, count) ->
-        appendLine("  ${state.name}: $count")
-      }
-    }
-  }
-}
-
 private fun ArchiveUploadProgressState.toPrettyString(): String {
  return buildString {
    appendLine("state: ${state.name}")
--- a/core-util/src/main/java/org/signal/core/util/SQLiteDatabaseExtensions.kt
+++ b/core-util/src/main/java/org/signal/core/util/SQLiteDatabaseExtensions.kt
@@ -338,6 +338,10 @@ class SelectBuilderPart3(
    return SelectBuilderPart4b(db, columns, tableName, where, whereArgs, "$offset,$limit")
  }

+  fun groupBy(groupBy: String): SelectBuilderPart4c {
+    return SelectBuilderPart4c(db, columns, tableName, where, whereArgs, groupBy)
+  }
+
  fun run(): Cursor {
    return db.query(
      SupportSQLiteQueryBuilder
@@ -405,6 +409,27 @@ class SelectBuilderPart4b(
  }
 }

+class SelectBuilderPart4c(
+  private val db: SupportSQLiteDatabase,
+  private val columns: Array<String>,
+  private val tableName: String,
+  private val where: String,
+  private val whereArgs: Array<String>,
+  private val groupBy: String
+) {
+
+  fun run(): Cursor {
+    return db.query(
+      SupportSQLiteQueryBuilder
+        .builder(tableName)
+        .columns(columns)
+        .selection(where, whereArgs)
+        .groupBy(groupBy)
+        .create()
+    )
+  }
+}
+
 class SelectBuilderPart5(
  private val db: SupportSQLiteDatabase,
  private val columns: Array<String>,