From 9021883baaa61e5fff886e892e9f237b95c0d7d8 Mon Sep 17 00:00:00 2001 From: Greyson Parrelli Date: Fri, 12 Sep 2025 12:02:04 -0400 Subject: [PATCH] Improve debug logging for reconciliation. --- .../securesms/database/AttachmentTable.kt | 97 +++++++++++++++---- .../ArchiveAttachmentReconciliationJob.kt | 18 +++- .../jobs/ArchiveCommitAttachmentDeletesJob.kt | 12 +-- .../logsubmit/LogSectionRemoteBackups.kt | 33 +------ .../core/util/SQLiteDatabaseExtensions.kt | 25 +++++ 5 files changed, 124 insertions(+), 61 deletions(-) diff --git a/app/src/main/java/org/thoughtcrime/securesms/database/AttachmentTable.kt b/app/src/main/java/org/thoughtcrime/securesms/database/AttachmentTable.kt index 8a52ef9fe1..29811de00c 100644 --- 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 = mediaIds.map { it.value.toByteString() }.toSet() val found = mutableListOf>() - 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) { diff --git a/app/src/main/java/org/thoughtcrime/securesms/jobs/ArchiveAttachmentReconciliationJob.kt b/app/src/main/java/org/thoughtcrime/securesms/jobs/ArchiveAttachmentReconciliationJob.kt index dc1e913243..88cf055f3b 100644 --- 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}") + } } } diff --git a/app/src/main/java/org/thoughtcrime/securesms/jobs/ArchiveCommitAttachmentDeletesJob.kt b/app/src/main/java/org/thoughtcrime/securesms/jobs/ArchiveCommitAttachmentDeletesJob.kt index f3ecf58b2a..83443f8104 100644 --- 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, 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())) } } diff --git a/app/src/main/java/org/thoughtcrime/securesms/logsubmit/LogSectionRemoteBackups.kt b/app/src/main/java/org/thoughtcrime/securesms/logsubmit/LogSectionRemoteBackups.kt index 96be28cfe6..2d14724865 100644 --- 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}") diff --git a/core-util/src/main/java/org/signal/core/util/SQLiteDatabaseExtensions.kt b/core-util/src/main/java/org/signal/core/util/SQLiteDatabaseExtensions.kt index 1b7108a3d2..9383ac25d6 100644 --- 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, + private val tableName: String, + private val where: String, + private val whereArgs: Array, + 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,