Improvements to Backups logging

This commit is contained in:
Sasha Weiss 2025-09-11 16:05:45 -07:00 committed by GitHub
parent 1c83951e89
commit fa57658ee1
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
12 changed files with 59 additions and 47 deletions

View File

@ -1122,6 +1122,8 @@ extension BackupArchive {
fileprivate static let maxCollapsedIdLogCount = 10
public struct CollapsedErrorLog {
private let logger: PrefixedLogger
public private(set) var typeLogString: String
public private(set) var exampleCallsiteString: String
public private(set) var exampleProtoFrameJson: String?
@ -1131,6 +1133,8 @@ extension BackupArchive {
public private(set) var logLevel: BackupArchive.LogLevel
init(_ error: LoggableErrorAndProto) {
self.logger = PrefixedLogger(prefix: "[Backups]")
self.typeLogString = error.error.typeLogString
self.exampleCallsiteString = error.error.callsiteLogString
self.exampleProtoFrameJson = error.protoJson
@ -1160,9 +1164,9 @@ extension BackupArchive {
+ "example callsite: \(exampleCallsiteString)"
switch logLevel {
case .warning:
Logger.warn(logString)
logger.warn(logString)
case .error:
Logger.error(logString)
logger.error(logString)
}
}
}

View File

@ -187,7 +187,6 @@ public class BackupArchivePostFrameRestoreActionManager {
/// without a chat existing. However, who's to say what we'll import
/// and it's not illegal to create a Backup with a `Contact` frame
/// that doesn't have a corresponding `Chat` frame.
Logger.warn("Skipping insert of contact-hidden info message: missing contact thread for recipient!")
return
}
@ -208,7 +207,6 @@ public class BackupArchivePostFrameRestoreActionManager {
case .contact(let contactAddress) = address,
let phoneNumber = contactAddress.e164
else {
Logger.warn("Skipping insert of phone number missing ACI because there's no phone number!")
return
}
AuthorMergeHelper().foundMissingAci(for: phoneNumber.stringValue, tx: chatItemContext.tx)

View File

@ -76,7 +76,8 @@ class BackupArchiveInlinedOversizeTextArchiver {
private let attachmentContentValidator: AttachmentContentValidator
private let attachmentManager: AttachmentManager
private let attachmentStore: AttachmentStore
private let db: any DB
private let db: DB
private let logger: PrefixedLogger
private static let lastRestoredRowIdKey = "lastRestoredRowIdKey"
private let kvStore = KeyValueStore(collection: "BackupOversizeTextCacheStore")
@ -88,13 +89,14 @@ class BackupArchiveInlinedOversizeTextArchiver {
attachmentContentValidator: AttachmentContentValidator,
attachmentManager: AttachmentManager,
attachmentStore: AttachmentStore,
db: any DB,
db: DB,
) {
self.attachmentsArchiver = attachmentsArchiver
self.attachmentContentValidator = attachmentContentValidator
self.attachmentManager = attachmentManager
self.attachmentStore = attachmentStore
self.db = db
self.logger = PrefixedLogger(prefix: "[Backups]")
}
// MARK: - Archive
@ -416,7 +418,7 @@ class BackupArchiveInlinedOversizeTextArchiver {
private func insert(attachmentId: Attachment.IDType, text: String, tx: DBWriteTransaction) throws -> BackupOversizeTextCache.IDType {
var text = text
if text.lengthOfBytes(using: .utf8) > BackupOversizeTextCache.maxTextLengthBytes {
Logger.error("Oversized backup text too long! Truncating...")
logger.error("Oversized backup text too long! Truncating...")
text = text.trimToUtf8ByteCount(BackupOversizeTextCache.maxTextLengthBytes)
}
var record = BackupOversizeTextCache(id: nil, attachmentRowId: attachmentId, text: text)

View File

@ -420,7 +420,6 @@ final class BackupArchiveSimpleChatUpdateArchiver {
))
case .releaseChannelDonationRequest:
// TODO: [Backups] Add support (and a test case!) for this once we've implemented the Release Notes channel.
logger.warn("Encountered not-yet-supported release-channel-donation-request update")
return .success(())
case .endSession:
guard let senderRecipient = context.recipientContext[chatItem.authorRecipientId] else {

View File

@ -135,7 +135,6 @@ public class BackupArchiveContactRecipientArchiver: BackupArchiveProtoStreamWrit
else {
/// Skip recipients with no identifiers, but don't add to the
/// list of errors.
Logger.warn("Skipping empty SignalRecipient!")
return
}
@ -331,7 +330,6 @@ public class BackupArchiveContactRecipientArchiver: BackupArchiveProtoStreamWrit
else {
/// Skip profiles with no identifiers, but don't add to the
/// list of errors.
Logger.warn("Skipping empty OWSUserProfile!")
return
}

View File

@ -32,8 +32,6 @@ public class BackupArchiveGroupRecipientArchiver: BackupArchiveProtoStreamWriter
private let storyStore: BackupArchiveStoryStore
private let threadStore: BackupArchiveThreadStore
private let logger = PrefixedLogger(prefix: "[Backups]")
public init(
avatarDefaultColorManager: AvatarDefaultColorManager,
avatarFetcher: BackupArchiveAvatarFetcher,
@ -109,7 +107,6 @@ public class BackupArchiveGroupRecipientArchiver: BackupArchiveProtoStreamWriter
errors: inout [ArchiveFrameError]
) {
guard let groupModel = groupThread.groupModel as? TSGroupModelV2 else {
logger.warn("Skipping archive of V1 group.")
return
}

View File

@ -15,8 +15,6 @@ public class BackupArchiveReleaseNotesRecipientArchiver: BackupArchiveProtoStrea
typealias ArchiveFrameResult = BackupArchive.ArchiveSingleFrameResult<Void, RecipientAppId>
typealias RestoreFrameResult = BackupArchive.RestoreFrameResult<RecipientId>
private let logger = PrefixedLogger(prefix: "[Backups]")
public init() {}
// MARK: -
@ -62,7 +60,6 @@ public class BackupArchiveReleaseNotesRecipientArchiver: BackupArchiveProtoStrea
context[recipient.recipientId] = .releaseNotesChannel
// TODO: [Backups] Implement restoring the Release Notes channel recipient.
logger.warn("No-op restore of a Release Notes recipient!")
return .success
}
}

View File

@ -126,14 +126,14 @@ extension BackupArchive {
}
override func logResults() {
Logger.info("Pre-Frame Restore Metrics:")
logger.info("Pre-Frame Restore Metrics:")
for (action, metrics) in self.preFrameRestoreMetrics.sorted(by: { $0.value.totalDurationMs > $1.value.totalDurationMs }) {
logMetrics(metrics, typeString: action.rawValue)
}
super.logResults()
Logger.info("Post-Frame Restore Metrics:")
logger.info("Post-Frame Restore Metrics:")
for (action, metrics) in self.postFrameRestoreMetrics.sorted(by: { $0.value.totalDurationMs > $1.value.totalDurationMs }) {
logMetrics(metrics, typeString: action.rawValue)
}
@ -171,6 +171,8 @@ extension BackupArchive {
class DBFileSizeBencher {
private let dateProvider: DateProviderMonotonic
private let dbFileSizeProvider: DBFileSizeProvider
private let logger: PrefixedLogger
#if DEBUG
private let secondsBetweenLogs: TimeInterval = 2
#else
@ -188,6 +190,7 @@ extension BackupArchive {
) {
self.dateProvider = dateProvider
self.dbFileSizeProvider = dbFileSizeProvider
self.logger = PrefixedLogger(prefix: "[Backups]")
}
func logIfNecessary(totalFramesProcessed: UInt64) {
@ -201,7 +204,7 @@ extension BackupArchive {
let dbFileSize = dbFileSizeProvider.getDatabaseFileSize()
let walFileSize = dbFileSizeProvider.getDatabaseWALFileSize()
Logger.info("{DB:\(dbFileSize), WAL:\(walFileSize), frames:\(totalFramesProcessed), framesDelta:\(totalFramesProcessed - (lastTotalFramesProcessed ?? 0))}")
logger.info("{DB:\(dbFileSize), WAL:\(walFileSize), frames:\(totalFramesProcessed), framesDelta:\(totalFramesProcessed - (lastTotalFramesProcessed ?? 0))}")
lastLogDate = dateProvider()
lastTotalFramesProcessed = totalFramesProcessed
@ -215,10 +218,10 @@ extension BackupArchive {
/// archive/restore, per frame type.
class Bencher {
fileprivate let dateProvider: DateProviderMonotonic
fileprivate let logger: PrefixedLogger
fileprivate let memorySampler: MemorySampler
fileprivate let startDate: MonotonicDate
fileprivate var totalFramesProcessed: UInt64 = 0
fileprivate var frameProcessingMetrics = [FrameType: Metrics]()
@ -227,6 +230,7 @@ extension BackupArchive {
memorySampler: MemorySampler
) {
self.dateProvider = dateProviderMonotonic
self.logger = PrefixedLogger(prefix: "[Backups]")
self.memorySampler = memorySampler
startDate = dateProviderMonotonic()
@ -312,9 +316,9 @@ extension BackupArchive {
func logResults() {
let totalFrameCount = frameProcessingMetrics.reduce(0, { $0 + $1.value.frameCount })
Logger.info("Processed \(loggableCountString(totalFrameCount)) frames in \((dateProvider() - startDate).milliseconds)ms")
logger.info("Processed \(loggableCountString(totalFrameCount)) frames in \((dateProvider() - startDate).milliseconds)ms")
Logger.info("Frame Processing Metrics:")
logger.info("Frame Processing Metrics:")
for (frameType, metrics) in self.frameProcessingMetrics.sorted(by: { $0.value.totalDurationMs > $1.value.totalDurationMs }) {
logMetrics(metrics, typeString: frameType.rawValue)
}
@ -330,7 +334,7 @@ extension BackupArchive {
if metrics.totalEnumerationDurationMs > 0 {
logString += " Enum:\(metrics.totalEnumerationDurationMs)ms"
}
Logger.info(logString)
logger.info(logString)
}
private func loggableCountString(_ number: UInt64) -> String {

View File

@ -31,6 +31,7 @@ public class BackupArchiveFullTextSearchIndexerImpl: BackupArchiveFullTextSearch
private let fullTextSearchIndexer: Shims.FullTextSearchIndexer
private let interactionStore: InteractionStore
private let kvStore: KeyValueStore
private let logger: PrefixedLogger
private let searchableNameIndexer: SearchableNameIndexer
private let taskQueue: SerialTaskQueue
@ -48,6 +49,7 @@ public class BackupArchiveFullTextSearchIndexerImpl: BackupArchiveFullTextSearch
self.fullTextSearchIndexer = fullTextSearchIndexer
self.interactionStore = interactionStore
self.kvStore = KeyValueStore(collection: "BackupFullTextSearchIndexerImpl")
self.logger = PrefixedLogger(prefix: "[Backups]")
self.searchableNameIndexer = searchableNameIndexer
self.taskQueue = SerialTaskQueue()
@ -108,7 +110,7 @@ public class BackupArchiveFullTextSearchIndexerImpl: BackupArchiveFullTextSearch
if maxInteractionRowIdSoFar >= maxInteractionRowIdInclusive {
self.setMaxInteractionRowIdInclusive(nil, tx: tx)
self.setMinInteractionRowIdExclusive(nil, tx: tx)
Logger.info("Finished")
logger.info("Finished")
} else {
minInteractionRowIdExclusive = maxInteractionRowIdSoFar
self.setMinInteractionRowIdExclusive(maxInteractionRowIdSoFar, tx: tx)
@ -116,7 +118,7 @@ public class BackupArchiveFullTextSearchIndexerImpl: BackupArchiveFullTextSearch
}
}
Logger.info("Starting job")
logger.info("Starting job")
var hasMoreMessages = true
while hasMoreMessages {
@ -135,7 +137,7 @@ public class BackupArchiveFullTextSearchIndexerImpl: BackupArchiveFullTextSearch
while let interaction = try cursor.next() {
let durationMs = (dateProvider() - startTime).milliseconds
if durationMs > Constants.batchDurationMs {
Logger.info("Bailing on batch after \(processedCount) interactions")
logger.info("Bailing on batch after \(processedCount) interactions")
finalizeBatch(tx: tx)
return true
}
@ -146,7 +148,7 @@ public class BackupArchiveFullTextSearchIndexerImpl: BackupArchiveFullTextSearch
finalizeBatch(tx: tx)
return false
} catch let error {
Logger.info("Failed batch after \(processedCount) interactions \(error.grdbErrorForLogging)")
logger.info("Failed batch after \(processedCount) interactions \(error.grdbErrorForLogging)")
finalizeBatch(tx: tx)
return true
}

View File

@ -64,6 +64,7 @@ public class BackupArchiveManagerImpl: BackupArchiveManager {
private let libsignalNet: LibSignalClient.Net
private let localStorage: AccountKeyStore
private let localRecipientArchiver: BackupArchiveLocalRecipientArchiver
private let logger: PrefixedLogger
private let messagePipelineSupervisor: MessagePipelineSupervisor
private let oversizeTextArchiver: BackupArchiveInlinedOversizeTextArchiver
private let plaintextStreamProvider: BackupArchivePlaintextProtoStreamProvider
@ -145,6 +146,7 @@ public class BackupArchiveManagerImpl: BackupArchiveManager {
self.libsignalNet = libsignalNet
self.localStorage = localStorage
self.localRecipientArchiver = localRecipientArchiver
self.logger = PrefixedLogger(prefix: "[Backups]")
self.messagePipelineSupervisor = messagePipelineSupervisor
self.oversizeTextArchiver = oversizeTextArchiver
self.plaintextStreamProvider = plaintextStreamProvider
@ -208,7 +210,7 @@ public class BackupArchiveManagerImpl: BackupArchiveManager {
} catch let error {
switch (error as? BackupArchive.Response.BackupUploadFormError) {
case .tooLarge:
Logger.warn("Backup too large! \(metadata.encryptedDataLength)")
logger.warn("Backup too large! \(metadata.encryptedDataLength)")
default:
break
}
@ -462,7 +464,7 @@ public class BackupArchiveManagerImpl: BackupArchiveManager {
var errors = [LoggableErrorAndProto]()
let result = Result<Void, Error>(catching: {
Logger.info("Exporting for \(purposeString) with version \(backupVersion), timestamp \(startTimestampMs)")
logger.info("Exporting for \(purposeString) with version \(backupVersion), timestamp \(startTimestampMs)")
try autoreleasepool {
try writeHeader(
@ -673,7 +675,7 @@ public class BackupArchiveManagerImpl: BackupArchiveManager {
try stream.closeFileStream()
Logger.info("Finished exporting backup")
logger.info("Finished exporting backup")
bencher.logResults()
})
processErrors(errors: errors, didFail: result.isSuccess.negated)
@ -978,7 +980,7 @@ public class BackupArchiveManagerImpl: BackupArchiveManager {
throw error
}
Logger.info("Importing with version \(backupInfo.version), timestamp \(backupInfo.backupTimeMs)")
logger.info("Importing with version \(backupInfo.version), timestamp \(backupInfo.backupTimeMs)")
guard backupInfo.version == Constants.supportedBackupVersion else {
frameErrors.append(LoggableErrorAndProto(
@ -1361,9 +1363,9 @@ public class BackupArchiveManagerImpl: BackupArchiveManager {
disappearingMessagesJob.startIfNecessary()
}
Logger.info("Imported with version \(backupInfo.version), timestamp \(backupInfo.backupTimeMs)")
Logger.info("Backup app version: \(backupInfo.currentAppVersion.nilIfEmpty ?? "Missing!")")
Logger.info("Backup first app version: \(backupInfo.firstAppVersion.nilIfEmpty ?? "Missing!")")
logger.info("Imported with version \(backupInfo.version), timestamp \(backupInfo.backupTimeMs)")
logger.info("Backup app version: \(backupInfo.currentAppVersion.nilIfEmpty ?? "Missing!")")
logger.info("Backup first app version: \(backupInfo.firstAppVersion.nilIfEmpty ?? "Missing!")")
bencher.logResults()
return backupInfo
@ -1447,7 +1449,7 @@ public class BackupArchiveManagerImpl: BackupArchiveManager {
}
if wasFrameDropped {
// Log this specifically so we can do a naive exact text search in debug logs.
Logger.error("Dropped frame(s) on backup export or import!!!")
logger.error("Dropped frame(s) on backup export or import!!!")
}
// Only present errors if some error rises above warning.
// (But if one does, present _all_ errors).
@ -1500,16 +1502,16 @@ public class BackupArchiveManagerImpl: BackupArchiveManager {
switch error {
case let validationError as MessageBackupValidationError:
await backupArchiveErrorPresenter.persistValidationError(validationError)
Logger.error("Backup validation failed \(validationError.errorMessage)")
logger.error("Backup validation failed \(validationError.errorMessage)")
throw BackupValidationError.validationFailed(
message: validationError.errorMessage,
unknownFields: validationError.unknownFields.fields
)
case SignalError.ioError(let description):
Logger.error("Backup validation i/o error: \(description)")
logger.error("Backup validation i/o error: \(description)")
throw BackupValidationError.ioError(description)
default:
Logger.error("Backup validation unknown error: \(error)")
logger.error("Backup validation unknown error: \(error)")
throw BackupValidationError.unknownError
}
}

View File

@ -117,6 +117,7 @@ public enum SVR🐝Error: Error, Equatable, IsRetryableProvider {
// MARK: - Encryption Key Derivation
extension BackupImportSource {
private var logger: PrefixedLogger { .init(prefix: "[Backups]") }
/// Derive the encryption key used to decrypt the backup file, potentially
/// performing a fetch from SVR🐝, depending on the purpose and available data.
@ -213,20 +214,20 @@ extension BackupImportSource {
switch error as? LibSignalClient.SignalError {
case .invalidArgument:
// Metadata is malformed. Totally unrecoverable.
Logger.error("SVR🐝 metadata header malformed; cannot recover backup")
logger.error("SVR🐝 metadata header malformed; cannot recover backup")
throw .unrecoverable
case .svrRestoreFailed:
// Some SVR🐝 error that means data is lost. Totally unrecoverable.
Logger.error("SVR🐝 restore failed; cannot recover backup")
logger.error("SVR🐝 restore failed; cannot recover backup")
throw .unrecoverable
case .svrDataMissing:
Logger.error("SVR🐝 data missing; cannot recover backup")
logger.error("SVR🐝 data missing; cannot recover backup")
throw .incorrectRecoveryKey
case .rateLimitedError(let retryAfter, _):
// Do a quite rudimentary thing where we just wait
// for the retry time, which will leave the user with
// a spinner. But we never really expect this to happen.
Logger.warn("Rate-limited SVR🐝 restore, waiting...")
logger.warn("Rate-limited SVR🐝 restore, waiting...")
try? await Task.sleep(nanoseconds: retryAfter.clampedNanoseconds)
return try await fetchForwardSecrecyTokenFromSvr(
key: key,
@ -245,7 +246,7 @@ extension BackupImportSource {
default:
// Everything else let the user retry. This will inevitably
// include things that are bugs, leaving users in retry loops.
Logger.error("Failed SVR🐝 restore w/ unknown error: \(error)")
logger.error("Failed SVR🐝 restore w/ unknown error: \(error)")
throw .retryableByUser
}
}
@ -271,6 +272,7 @@ extension BackupImportSource {
}
extension BackupExportPurpose {
private var logger: PrefixedLogger { .init(prefix: "[Backups]") }
struct EncryptionMetadata {
let encryptionKey: MessageBackupKey
@ -392,7 +394,7 @@ extension BackupExportPurpose {
case .invalidArgument:
// This happens when the "previousSecretData" is invalid.
// To recover, we have to start over with `createNewBackupChain`.
Logger.error("Failed SVR🐝 store w/ invalid argument, wiping next secret metadata")
logger.error("Failed SVR🐝 store w/ invalid argument, wiping next secret metadata")
await db.awaitableWrite { tx in
nonceStore.deleteNextSecretMetadata(tx: tx)
}
@ -409,7 +411,7 @@ extension BackupExportPurpose {
// Do a quite rudimentary thing where we just wait
// for the retry time, which will leave the user with
// a spinner. But we never really expect this to happen.
Logger.warn("Rate-limited SVR🐝 store, waiting...")
logger.warn("Rate-limited SVR🐝 store, waiting...")
try? await Task.sleep(nanoseconds: NSEC_PER_MSEC * UInt64(retryAfter * 1000))
return try await storeEncryptionMetadataToSvr🐝(
key: key,
@ -427,7 +429,7 @@ extension BackupExportPurpose {
default:
// Everything else let the user retry. This will inevitably
// include things that are bugs, leaving users in retry loops.
Logger.error("Failed SVR🐝 store w/ unknown error: \(error)")
logger.error("Failed SVR🐝 store w/ unknown error: \(error)")
throw .retryableByUser
}
}

View File

@ -29,9 +29,16 @@ public enum BackupExportJobStep: String, OWSSequentialProgressStep {
}
}
public enum BackupExportJobMode {
public enum BackupExportJobMode: CustomStringConvertible {
case manual(OWSSequentialProgressRootSink<BackupExportJobStep>)
case bgProcessingTask
public var description: String {
switch self {
case .manual: "Manual"
case .bgProcessingTask: "BGProcessingTask"
}
}
}
public enum BackupExportJobError: Error {