From d11cbf97da9e6729d6b65e54949df2fd6caccf9d Mon Sep 17 00:00:00 2001 From: Michelle Linington Date: Tue, 19 Oct 2021 21:06:07 -0700 Subject: [PATCH 1/3] Log additional info on receiving a resend request If someone requests a resend for a failed group message, we should log out information about all of the groups the requester is a member of and when they last were sent an SKDM --- .../Messages/MessageSender+SenderKey.swift | 38 ++++-- .../src/Messages/OWSMessageManager.swift | 8 +- .../src/Messages/OWSOutgoingResendResponse.m | 10 +- .../Storage/AxolotlStore/SenderKeyStore.swift | 122 ++++++++++++++++-- 4 files changed, 148 insertions(+), 30 deletions(-) diff --git a/SignalServiceKit/src/Messages/MessageSender+SenderKey.swift b/SignalServiceKit/src/Messages/MessageSender+SenderKey.swift index f88643f7bd..a550ff8161 100644 --- a/SignalServiceKit/src/Messages/MessageSender+SenderKey.swift +++ b/SignalServiceKit/src/Messages/MessageSender+SenderKey.swift @@ -370,19 +370,19 @@ extension MessageSender { // to *also* fail the original message send. firstly { () -> Promise in MessageSender.ensureSessions(forMessageSends: skdmSends, ignoreErrors: true) - }.then(on: self.senderKeyQueue) { _ -> Guarantee<[Result]> in + }.then(on: self.senderKeyQueue) { _ -> Guarantee<[Result]> in // For each SKDM request we kick off a sendMessage promise. - // - If it succeeds, great! Record a successful delivery - // - Otherwise, invoke the sendErrorBlock + // - If it succeeds, great! Propogate along the successful OWSMessageSend + // - Otherwise, invoke the sendErrorBlock and rethrow so it gets packaged into the Guarantee // We use when(resolved:) because we want the promise to wait for // all sub-promises to finish, even if some failed. Guarantee.when(resolved: skdmSends.map { messageSend in return firstly { () -> AnyPromise in self.sendMessage(toRecipient: messageSend) return messageSend.asAnyPromise - }.map(on: self.senderKeyQueue) { _ -> SignalServiceAddress in - messageSend.address - }.recover(on: self.senderKeyQueue) { error -> Promise in + }.map(on: self.senderKeyQueue) { _ -> OWSMessageSend in + messageSend + }.recover(on: self.senderKeyQueue) { error -> Promise in // Note that we still rethrow. It's just easier to access the address // while we still have the messageSend in scope. let wrappedError = SenderKeyError.recipientSKDMFailed(error) @@ -392,22 +392,32 @@ extension MessageSender { }) } }.map(on: self.senderKeyQueue) { resultArray -> [SignalServiceAddress] in - // We only want to pass along recipients capable of receiving a senderKey message - let successfulSends: [SignalServiceAddress] = resultArray.compactMap { result in + // This is a hot path, so we do a bit of a dance here to prepare all of the successful send + // info before opening the write transaction. We need the recipient address and the SKDM + // timestamp. + let successfulSendInfo: [(recipient: SignalServiceAddress, timestamp: UInt64)] + + successfulSendInfo = resultArray.compactMap { result in switch result { - case let .success(address): return address - case .failure: return nil + case let .success(messageSend): + return (recipient: messageSend.address, timestamp: messageSend.message.timestamp) + case .failure: + return nil } } - if successfulSends.count > 0 { + + if successfulSendInfo.count > 0 { try self.databaseStorage.write { writeTx in - try successfulSends.forEach { - try self.senderKeyStore.recordSenderKeySent(for: thread, to: $0, writeTx: writeTx) + try successfulSendInfo.forEach { + try self.senderKeyStore.recordSenderKeySent(for: thread, + to: $0.recipient, + timestamp: $0.timestamp, + writeTx: writeTx) } } } // We want to return all recipients that are now ready for sender key - return Array(recipientsNotNeedingSKDM) + successfulSends + return Array(recipientsNotNeedingSKDM) + successfulSendInfo.map { $0.recipient } }.recover(on: senderKeyQueue) { error in // If we hit *any* error that we haven't handled, we should fail the send diff --git a/SignalServiceKit/src/Messages/OWSMessageManager.swift b/SignalServiceKit/src/Messages/OWSMessageManager.swift index e140cc9f40..b23a650213 100644 --- a/SignalServiceKit/src/Messages/OWSMessageManager.swift +++ b/SignalServiceKit/src/Messages/OWSMessageManager.swift @@ -187,10 +187,11 @@ extension OWSMessageManager { } let protocolAddress = try ProtocolAddress(from: sourceAddress, deviceId: sourceDeviceId) - // If a ratchet key is included, this was a 1:1 session message - // Archive the session if the current key matches. let didPerformSessionReset: Bool + if let ratchetKey = errorMessage.ratchetKey { + // If a ratchet key is included, this was a 1:1 session message + // Archive the session if the current key matches. let sessionRecord = try sessionStore.loadSession(for: protocolAddress, context: writeTx) if try sessionRecord?.currentRatchetKeyMatches(ratchetKey) == true { Logger.info("Decryption error included ratchet key. Archiving...") @@ -203,6 +204,9 @@ extension OWSMessageManager { didPerformSessionReset = false } } else { + // If we don't have a ratchet key, this was a sender key session message. + // Let's log any info about SKDMs that we had sent to the address requesting resend + senderKeyStore.logSKDMInfo(for: sourceAddress, transaction: writeTx) didPerformSessionReset = false } diff --git a/SignalServiceKit/src/Messages/OWSOutgoingResendResponse.m b/SignalServiceKit/src/Messages/OWSOutgoingResendResponse.m index 1fa6c020a2..61196a0c46 100644 --- a/SignalServiceKit/src/Messages/OWSOutgoingResendResponse.m +++ b/SignalServiceKit/src/Messages/OWSOutgoingResendResponse.m @@ -115,8 +115,16 @@ if (self.didAppendSKDM) { TSThread *originalThread = [TSThread anyFetchWithUniqueId:self.originalThreadId transaction:transaction]; if (originalThread.isGroupThread) { + NSError *error = nil; TSGroupThread *groupThread = (TSGroupThread *)originalThread; - [self.senderKeyStore recordSenderKeySentFor:groupThread to:recipientAddress writeTx:transaction error:nil]; + [self.senderKeyStore recordSenderKeySentFor:groupThread + to:recipientAddress + timestamp:self.timestamp + writeTx:transaction + error:&error]; + if (error) { + OWSFailDebug(@"Unexpected error when updating sender key store: %@", error); + } } else { OWSFailDebug(@"Appended an SKDM but not a group thread. Not expected."); } diff --git a/SignalServiceKit/src/Storage/AxolotlStore/SenderKeyStore.swift b/SignalServiceKit/src/Storage/AxolotlStore/SenderKeyStore.swift index f08f3f15e0..15858b7ec3 100644 --- a/SignalServiceKit/src/Storage/AxolotlStore/SenderKeyStore.swift +++ b/SignalServiceKit/src/Storage/AxolotlStore/SenderKeyStore.swift @@ -48,12 +48,14 @@ public class SenderKeyStore: NSObject { // Iterate over each cached recipient. If no new devices or reregistrations have occurred since // we last recorded an SKDM send, we can skip sending to them. - for (address, cachedRecipientState) in keyMetadata.keyRecipients { + for (address, sendInfo) in keyMetadata.sentKeyInfo { do { + let priorSendRecipientState = sendInfo.keyRecipient + // Only remove the recipient in question from our send targets if the cached state contains // every device from the current state. Any new devices mean we need to re-send. let currentRecipientState = try KeyRecipient.currentState(for: address, transaction: readTx) - if cachedRecipientState.containsEveryDevice(from: currentRecipientState) { + if priorSendRecipientState.containsEveryDevice(from: currentRecipientState) { addressesNeedingSenderKey.remove(address) } } catch { @@ -75,6 +77,7 @@ public class SenderKeyStore: NSObject { public func recordSenderKeySent( for thread: TSGroupThread, to address: SignalServiceAddress, + timestamp: UInt64, writeTx: SDSAnyWriteTransaction) throws { try storageLock.withLock { guard let keyId = keyIdForSendingToThreadId(thread.threadUniqueId, writeTx: writeTx), @@ -82,7 +85,7 @@ public class SenderKeyStore: NSObject { throw OWSAssertionError("Failed to look up key metadata") } var updatedMetadata = existingMetadata - updatedMetadata.keyRecipients[address] = try KeyRecipient.currentState(for: address, transaction: writeTx) + try updatedMetadata.recordSKMDSent(at: timestamp, address: address, transaction: writeTx) setMetadata(updatedMetadata, writeTx: writeTx) } } @@ -99,7 +102,7 @@ public class SenderKeyStore: NSObject { return } var updatedMetadata = existingMetadata - updatedMetadata.keyRecipients[address] = nil + updatedMetadata.resetDeliveryRecord(for: address) setMetadata(updatedMetadata, writeTx: writeTx) } } @@ -110,9 +113,8 @@ public class SenderKeyStore: NSObject { guard let keyId = keyIdForSendingToThreadId(thread.threadUniqueId, readTx: readTx), let keyMetadata = getKeyMetadata(for: keyId, readTx: readTx) else { return false } - let currentKeyRecipients = Set(keyMetadata.keyRecipients.keys) let currentGroupMembership = thread.groupMembership.fullMembers - let didSomeoneLeaveTheGroup = currentKeyRecipients.subtracting(currentGroupMembership).count > 0 + let didSomeoneLeaveTheGroup = keyMetadata.currentRecipients.subtracting(currentGroupMembership).count > 0 return keyMetadata.isValid && !didSomeoneLeaveTheGroup } @@ -330,9 +332,69 @@ extension SenderKeyStore { } } } + + // MARK: Logging + + static private var logThrottleExpiration = Date.distantPast + + // This method traverses all groups where `recipient` is a member and logs out information on any sent + // sender key distribution messages. + public func logSKDMInfo(for recipient: SignalServiceAddress, transaction: SDSAnyReadTransaction) { + guard let localUuid = tsAccountManager.localUuid else { return } + + // To avoid doing too much work for a flood of failed decryptions, we'll only honor an SKDM log + // dump request every 10s. That's frequent enough to be captured in a log zip. + guard Self.logThrottleExpiration.isBeforeNow else { + Logger.info("Dumped SKDM logs recently. Ignoring request for \(recipient)...") + return + } + Self.logThrottleExpiration = Date() + 10.0 + + // We deliberately avoid the cached pathways here and just query the database directly + // Locality isn't super useful when we're just iterating over everything. This would just + // cache a bunch of memory that we might not end up using later. + Logger.info("Logging info about all SKDMs sent to \(recipient)") + for commonThread in TSGroupThread.groupThreads(with: recipient, transaction: transaction) { + autoreleasepool { + let threadId = commonThread.threadUniqueId + let distributionIdString = sendingDistributionIdStore.getString(threadId, transaction: transaction) + let distributionId = distributionIdString.flatMap { UUID(uuidString: $0) } + guard let distributionId = distributionId else { return } + + // Once we have a distributionId, for a thread, we'll log *something* for the thread + let keyId = Self.buildKeyId(addressUuid: localUuid, distributionId: distributionId) + let keyMetadata: KeyMetadata? + do { + keyMetadata = try keyMetadataStore.getCodableValue(forKey: keyId, transaction: transaction) + } catch { + owsFailDebug("Failed to deserialize key metadata \(error)") + keyMetadata = nil + } + + let prefix = "--> Thread \(threadId) with distributionId \(distributionId): " + if let keyMetadata = keyMetadata, let sendInfo = keyMetadata.sentKeyInfo[recipient] { + Logger.info("\(prefix) Sent SKDM at timestamp: \(sendInfo.skdmTimestamp) for sender key created at: \(keyMetadata.creationDate)") + } else if let keyMetadata = keyMetadata { + Logger.info("\(prefix) Have not sent SKDM for sender key created at: \(keyMetadata.creationDate). SKDM sent to \(keyMetadata.sentKeyInfo.count) others") + } else { + Logger.info("\(prefix) No recorded key metadata") + } + } + } + } } // MARK: - Model + +// MARK: SKDMSendInfo + +/// Stores information about a sent SKDM +/// Currently just tracks the sent timestamp and the recipient. +private struct SKDMSendInfo: Codable { + let skdmTimestamp: UInt64 + let keyRecipient: KeyRecipient +} + // MARK: KeyRecipient /// Stores information about a recipient of a sender key @@ -434,8 +496,9 @@ private struct KeyMetadata { } let creationDate: Date - var keyRecipients: [SignalServiceAddress: KeyRecipient] var isForEncrypting: Bool + private(set) var sentKeyInfo: [SignalServiceAddress: SKDMSendInfo] + var currentRecipients: Set { Set(sentKeyInfo.keys) } init(record: SenderKeyRecord, sender: ProtocolAddress, distributionId: SenderKeyStore.DistributionId) throws { guard let uuid = sender.uuid else { @@ -449,7 +512,7 @@ private struct KeyMetadata { self.isForEncrypting = sender.isCurrentDevice self.creationDate = Date() - self.keyRecipients = [:] + self.sentKeyInfo = [:] } var isValid: Bool { @@ -460,6 +523,16 @@ private struct KeyMetadata { let expirationDate = creationDate.addingTimeInterval(kMonthInterval) return (expirationDate.isAfterNow && isForEncrypting) } + + mutating func resetDeliveryRecord(for address: SignalServiceAddress) { + sentKeyInfo[address] = nil + } + + mutating func recordSKMDSent(at timestamp: UInt64, address: SignalServiceAddress, transaction: SDSAnyReadTransaction) throws { + let recipient = try KeyRecipient.currentState(for: address, transaction: transaction) + let sendInfo = SKDMSendInfo(skdmTimestamp: timestamp, keyRecipient: recipient) + sentKeyInfo[address] = sendInfo + } } extension KeyMetadata: Codable { @@ -470,12 +543,17 @@ extension KeyMetadata: Codable { case recordData case creationDate - case keyRecipients + case sentKeyInfo case isForEncrypting + + enum LegacyKeys: String, CodingKey { + case keyRecipients + } } init(from decoder: Decoder) throws { let container = try decoder.container(keyedBy: CodingKeys.self) + let legacyValues = try decoder.container(keyedBy: CodingKeys.LegacyKeys.self) distributionId = try container.decode(SenderKeyStore.DistributionId.self, forKey: .distributionId) ownerUuid = try container.decode(UUID.self, forKey: .ownerUuid) @@ -484,10 +562,28 @@ extension KeyMetadata: Codable { creationDate = try container.decode(Date.self, forKey: .creationDate) isForEncrypting = try container.decode(Bool.self, forKey: .isForEncrypting) - // KeyRecipients is a V2 key replacing a different type that stored the same info, so it may not exist. - // A migration is overkill since these keys will expire after a month anyway. Resetting our keyRecipients - // to an empty dict will just mean we resend an SKDM before it's necessary - keyRecipients = try container.decodeIfPresent([SignalServiceAddress: KeyRecipient].self, forKey: .keyRecipients) ?? [:] + // There have been a few iterations of our delivery tracking. Briefly we have: + // - V1: We just recorded a mapping from UUID -> Set + // - V2: Record a mapping of SignalServiceAddress -> KeyRecipient. This allowed us to + // track additional info about the recipient of a key like registrationId + // - V3: Record a mapping of SignalServiceAddress -> SKDMSendInfo. This allows us to + // record even more information about the send that's not specific to the recipient. + // Right now, this is just used to record the SKDM timestamp. + // + // Hopefully this doesn't need to change in the future. We now have a place to hang information + // about the recipient (KeyRecipient) and the context of the sent SKDM (SKDMSendInfo) + if let sendInfo = try container.decodeIfPresent([SignalServiceAddress: SKDMSendInfo].self, forKey: .sentKeyInfo) { + Logger.info("michlin unwrapping v3: \(sendInfo)") + sentKeyInfo = sendInfo + } else if let keyRecipients = try legacyValues.decodeIfPresent([SignalServiceAddress: KeyRecipient].self, forKey: .keyRecipients) { + Logger.info("michlin performing migration from v2 to v3: \(keyRecipients)") + sentKeyInfo = keyRecipients.mapValues { SKDMSendInfo(skdmTimestamp: 0, keyRecipient: $0) } + } else { + // There's no way to migrate from our V1 storage. That's okay, we can just reset the dictionary. The only + // consequence here is we'll resend an SKDM that our recipients already have. No big deal. + owsFailDebug("") + sentKeyInfo = [:] + } } } From 30b5acd401aaa875ef87cea56a765e9a1d610add Mon Sep 17 00:00:00 2001 From: Michelle Linington Date: Tue, 19 Oct 2021 21:24:04 -0700 Subject: [PATCH 2/3] Remove leftover comments --- SignalServiceKit/src/Storage/AxolotlStore/SenderKeyStore.swift | 3 --- 1 file changed, 3 deletions(-) diff --git a/SignalServiceKit/src/Storage/AxolotlStore/SenderKeyStore.swift b/SignalServiceKit/src/Storage/AxolotlStore/SenderKeyStore.swift index 15858b7ec3..7431c03de7 100644 --- a/SignalServiceKit/src/Storage/AxolotlStore/SenderKeyStore.swift +++ b/SignalServiceKit/src/Storage/AxolotlStore/SenderKeyStore.swift @@ -573,15 +573,12 @@ extension KeyMetadata: Codable { // Hopefully this doesn't need to change in the future. We now have a place to hang information // about the recipient (KeyRecipient) and the context of the sent SKDM (SKDMSendInfo) if let sendInfo = try container.decodeIfPresent([SignalServiceAddress: SKDMSendInfo].self, forKey: .sentKeyInfo) { - Logger.info("michlin unwrapping v3: \(sendInfo)") sentKeyInfo = sendInfo } else if let keyRecipients = try legacyValues.decodeIfPresent([SignalServiceAddress: KeyRecipient].self, forKey: .keyRecipients) { - Logger.info("michlin performing migration from v2 to v3: \(keyRecipients)") sentKeyInfo = keyRecipients.mapValues { SKDMSendInfo(skdmTimestamp: 0, keyRecipient: $0) } } else { // There's no way to migrate from our V1 storage. That's okay, we can just reset the dictionary. The only // consequence here is we'll resend an SKDM that our recipients already have. No big deal. - owsFailDebug("") sentKeyInfo = [:] } } From 7be1f0981f18d8bff890f23b6b6c94c6d6e74e40 Mon Sep 17 00:00:00 2001 From: Michelle Linington Date: Tue, 26 Oct 2021 21:42:38 -0700 Subject: [PATCH 3/3] Atomic assignment for logThrottleExpiration --- .../src/Storage/AxolotlStore/SenderKeyStore.swift | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/SignalServiceKit/src/Storage/AxolotlStore/SenderKeyStore.swift b/SignalServiceKit/src/Storage/AxolotlStore/SenderKeyStore.swift index 7431c03de7..167506ecff 100644 --- a/SignalServiceKit/src/Storage/AxolotlStore/SenderKeyStore.swift +++ b/SignalServiceKit/src/Storage/AxolotlStore/SenderKeyStore.swift @@ -335,7 +335,7 @@ extension SenderKeyStore { // MARK: Logging - static private var logThrottleExpiration = Date.distantPast + static private var logThrottleExpiration = AtomicValue(Date.distantPast) // This method traverses all groups where `recipient` is a member and logs out information on any sent // sender key distribution messages. @@ -344,11 +344,11 @@ extension SenderKeyStore { // To avoid doing too much work for a flood of failed decryptions, we'll only honor an SKDM log // dump request every 10s. That's frequent enough to be captured in a log zip. - guard Self.logThrottleExpiration.isBeforeNow else { + guard Self.logThrottleExpiration.get().isBeforeNow else { Logger.info("Dumped SKDM logs recently. Ignoring request for \(recipient)...") return } - Self.logThrottleExpiration = Date() + 10.0 + Self.logThrottleExpiration.set(Date() + 10.0) // We deliberately avoid the cached pathways here and just query the database directly // Locality isn't super useful when we're just iterating over everything. This would just