From 581a0483083d257c968622d4651812ca5add647d Mon Sep 17 00:00:00 2001 From: NachoSoto Date: Fri, 11 Aug 2023 15:39:44 -0700 Subject: [PATCH] `CustomerInfoManager`: post transactions in parallel to POST receipts only once (#2954) The existing implementation was posting them in sequence, which meant that it was always going to make N requests. With this new implementation we can ensure that only one request is made for all transactions. --- .../OperationQueue+Extensions.swift | 4 ++ Sources/Identity/CustomerInfoManager.swift | 62 ++++++++++++------- .../Logging/Strings/CustomerInfoStrings.swift | 2 +- Sources/Logging/Strings/NetworkStrings.swift | 4 ++ .../BaseBackendIntegrationTests.swift | 2 +- .../OfflineStoreKitIntegrationTests.swift | 49 ++++++++++++--- ...StoreKitObserverModeIntegrationTests.swift | 30 +++++---- .../StoreKit2TransactionListenerTests.swift | 7 ++- .../StoreKitConfigTestCase+Extensions.swift | 9 +-- .../CustomerInfoManagerPostReceiptTests.swift | 42 +++++++------ .../Mocks/MockTransactionPoster.swift | 15 ++++- .../TestHelpers/AsyncTestHelpers.swift | 6 +- .../TestHelpers/TestLogHandler.swift | 35 +++++++++-- 13 files changed, 183 insertions(+), 84 deletions(-) diff --git a/Sources/FoundationExtensions/OperationQueue+Extensions.swift b/Sources/FoundationExtensions/OperationQueue+Extensions.swift index a809bcdd3d..f526632da6 100644 --- a/Sources/FoundationExtensions/OperationQueue+Extensions.swift +++ b/Sources/FoundationExtensions/OperationQueue+Extensions.swift @@ -22,6 +22,10 @@ extension OperationQueue { switch cacheStatus { case .firstCallbackAddedToList: self.addOperation(factory.create()) + + Logger.verbose(Strings.network.enqueing_operation(factory.operationType, + cacheKey: factory.cacheKey)) + case .addedToExistingInFlightList: Logger.debug( Strings.network.reusing_existing_request_for_operation( diff --git a/Sources/Identity/CustomerInfoManager.swift b/Sources/Identity/CustomerInfoManager.swift index f24de62e74..741bd1c508 100644 --- a/Sources/Identity/CustomerInfoManager.swift +++ b/Sources/Identity/CustomerInfoManager.swift @@ -321,35 +321,33 @@ private extension CustomerInfoManager { _ = Task { let transactions = await self.transactionFetcher.unfinishedVerifiedTransactions - if !transactions.isEmpty { - var results: [Result] = [] - let storefront = await Storefront.currentStorefront - + if let transactionToPost = transactions.first { Logger.debug( Strings.customerInfo.posting_transactions_in_lieu_of_fetching_customerinfo(transactions) ) - for transaction in transactions { - results.append( - await self.transactionPoster.handlePurchasedTransaction( - transaction, - data: .init(appUserID: appUserID, - presentedOfferingID: nil, - unsyncedAttributes: [:], - storefront: storefront, - source: Self.sourceForUnfinishedTransaction) - ) - ) - } + let transactionData = PurchasedTransactionData( + appUserID: appUserID, + presentedOfferingID: nil, + unsyncedAttributes: [:], + storefront: await Storefront.currentStorefront, + source: Self.sourceForUnfinishedTransaction + ) - // Any of the POST receipt operations will have posted the same receipt contents - // so the resulting `CustomerInfo` will be equivalent. - // For that reason, we can return the last known success if available, - // and otherwise the last result (an error). - let lastSuccess = results.last { $0.value != nil } - let result = lastSuccess ?? results.last! + // Post everything but the first transaction in the background + // in parallel so they can be de-duped + let otherTransactionsToPostInParalel = Array(transactions.dropFirst()) + Task.detached(priority: .background) { + await self.postTransactions(otherTransactionsToPostInParalel, transactionData) + } - completion(result) + // Return the result of posting the first transaction. + // The posted receipt will include the content of every other transaction + // so we don't need to wait for those. + completion(await self.transactionPoster.handlePurchasedTransaction( + transactionToPost, + data: transactionData + )) } else { self.requestCustomerInfo(appUserID: appUserID, isAppBackgrounded: isAppBackgrounded, @@ -376,6 +374,24 @@ private extension CustomerInfoManager { completion: completion) } + /// Posts all `transactions` in parallel. + @available(iOS 15.0, tvOS 15.0, macOS 12.0, watchOS 8.0, *) + private func postTransactions( + _ transactions: [StoreTransaction], + _ data: PurchasedTransactionData + ) async { + await withTaskGroup(of: Void.self) { group in + for transaction in transactions { + group.addTask { + _ = await self.transactionPoster.handlePurchasedTransaction( + transaction, + data: data + ) + } + } + } + } + // Note: this is just a best guess. private static let sourceForUnfinishedTransaction: PurchaseSource = .init( isRestore: false, diff --git a/Sources/Logging/Strings/CustomerInfoStrings.swift b/Sources/Logging/Strings/CustomerInfoStrings.swift index 5bfe4138de..4b2c6c002c 100644 --- a/Sources/Logging/Strings/CustomerInfoStrings.swift +++ b/Sources/Logging/Strings/CustomerInfoStrings.swift @@ -74,7 +74,7 @@ extension CustomerInfoStrings: LogMessage { return "There was an error communicating with RevenueCat servers. " + "CustomerInfo was temporarily computed offline, and it will be posted again as soon as possible." case let .posting_transactions_in_lieu_of_fetching_customerinfo(transactions): - return "Found unfinished transactions, will post receipt in lieu " + + return "Found \(transactions.count) unfinished transactions, will post receipt in lieu " + "of fetching CustomerInfo:\n\(transactions)" case let .updating_request_date(info, newRequestDate): return "Updating CustomerInfo '\(info.originalAppUserId)' request date: \(newRequestDate)" diff --git a/Sources/Logging/Strings/NetworkStrings.swift b/Sources/Logging/Strings/NetworkStrings.swift index 98b0b53443..4dfc3bf327 100644 --- a/Sources/Logging/Strings/NetworkStrings.swift +++ b/Sources/Logging/Strings/NetworkStrings.swift @@ -22,6 +22,7 @@ enum NetworkStrings { case api_request_failed(_ request: HTTPRequest, httpCode: HTTPStatusCode?, error: NetworkError) case api_request_failed_status_code(HTTPStatusCode) case reusing_existing_request_for_operation(CacheableNetworkOperation.Type, String) + case enqueing_operation(CacheableNetworkOperation.Type, cacheKey: String) case creating_json_error(error: String) case json_data_received(dataString: String) case parsing_json_error(error: Error) @@ -64,6 +65,9 @@ extension NetworkStrings: LogMessage { return "Network operation '\(operationType)' found with the same cache key " + "'\(cacheKey)'. Skipping request." + case let .enqueing_operation(operationType, cacheKey): + return "Enqueing network operation '\(operationType)' with cache key: '\(cacheKey)'" + case let .creating_json_error(error): return "Error creating request with body: \(error)" diff --git a/Tests/BackendIntegrationTests/BaseBackendIntegrationTests.swift b/Tests/BackendIntegrationTests/BaseBackendIntegrationTests.swift index 8a8d3a4269..4258a9c9e9 100644 --- a/Tests/BackendIntegrationTests/BaseBackendIntegrationTests.swift +++ b/Tests/BackendIntegrationTests/BaseBackendIntegrationTests.swift @@ -55,6 +55,7 @@ class BaseBackendIntegrationTests: TestCase { class var responseVerificationMode: Signing.ResponseVerificationMode { return .enforced(Signing.loadPublicKey()) } + var enableReceiptFetchRetry: Bool = true var apiKey: String { return Constants.apiKey } var proxyURL: String? { return Constants.proxyURL } @@ -215,7 +216,6 @@ private extension BaseBackendIntegrationTests { extension BaseBackendIntegrationTests: InternalDangerousSettingsType { - var enableReceiptFetchRetry: Bool { return true } var forceServerErrors: Bool { return self.serverIsDown } var forceSignatureFailures: Bool { return false } var testReceiptIdentifier: String? { return self.testUUID.uuidString } diff --git a/Tests/BackendIntegrationTests/OfflineStoreKitIntegrationTests.swift b/Tests/BackendIntegrationTests/OfflineStoreKitIntegrationTests.swift index c71e5d54b5..ba0edb4910 100644 --- a/Tests/BackendIntegrationTests/OfflineStoreKitIntegrationTests.swift +++ b/Tests/BackendIntegrationTests/OfflineStoreKitIntegrationTests.swift @@ -127,13 +127,12 @@ class OfflineStoreKit1IntegrationTests: BaseOfflineStoreKitIntegrationTests { // 3. Ensure delegate is notified of subscription try await asyncWait( - until: { [delegate = self.purchasesDelegate] in - delegate?.customerInfo?.activeSubscriptions.isEmpty == false - }, + description: "Subscription never became active", timeout: .seconds(5), - pollInterval: .milliseconds(200), - description: "Subscription never became active" - ) + pollInterval: .milliseconds(200) + ) { [delegate = self.purchasesDelegate] in + delegate?.customerInfo?.activeSubscriptions.isEmpty == false + } // 4. Ensure transaction is eventually finished try await self.logger.verifyMessageIsEventuallyLogged( @@ -243,6 +242,40 @@ class OfflineStoreKit1IntegrationTests: BaseOfflineStoreKitIntegrationTests { ) } + @available(iOS 15.0, tvOS 15.0, watchOS 8.0, macOS 12.0, *) + func testCallToGetCustomerInfoWithPendingTransactionsPostsReceiptOnlyOnce() async throws { + // This test requires the "production" behavior to make sure + // we don't refresh the receipt a second time when posting the second transaction. + self.enableReceiptFetchRetry = false + + self.serverDown() + + try await self.purchaseMonthlyProduct() + try self.testSession.forceRenewalOfSubscription( + productIdentifier: await self.monthlyPackage.storeProduct.productIdentifier + ) + + try await asyncWait(description: "Expected 2 unfinished transactions") { + await Transaction.unfinished.extractValues().count == 2 + } + + self.serverUp() + + let customerInfo = try await self.purchases.customerInfo(fetchPolicy: .fetchCurrent) + try await self.verifyEntitlementWentThrough(customerInfo) + + self.logger.verifyMessageWasLogged( + "Found 2 unfinished transactions, will post receipt in lieu of fetching CustomerInfo", + level: .debug, + expectedCount: 1 + ) + + try await self.logger.verifyMessageIsEventuallyLogged( + "Network operation 'PostReceiptDataOperation' found with the same cache key", + level: .debug + ) + } + @available(iOS 15.0, tvOS 15.0, watchOS 8.0, macOS 12.0, *) func testPurchasingConsumableInvalidatesOfflineMode() async throws { self.serverDown() @@ -318,7 +351,9 @@ class OfflineStoreKit1IntegrationTests: BaseOfflineStoreKitIntegrationTests { expect(info.nonSubscriptions.onlyElement?.productIdentifier) == Self.consumable10Coins // 6. Ensure transactions are finished - self.logger.verifyMessageWasLogged("Finishing transaction", level: .info, expectedCount: 2) + try await self.logger.verifyMessageIsEventuallyLogged("Finishing transaction", + level: .info, + expectedCount: 2) } } diff --git a/Tests/BackendIntegrationTests/StoreKitObserverModeIntegrationTests.swift b/Tests/BackendIntegrationTests/StoreKitObserverModeIntegrationTests.swift index ca7633a6af..4c1ed72787 100644 --- a/Tests/BackendIntegrationTests/StoreKitObserverModeIntegrationTests.swift +++ b/Tests/BackendIntegrationTests/StoreKitObserverModeIntegrationTests.swift @@ -54,17 +54,16 @@ class StoreKit2ObserverModeIntegrationTests: StoreKit1ObserverModeIntegrationTes XCTExpectFailure("This test currently does not pass (see FB12231111)") try await asyncWait( - until: { - let entitlement = await self.purchasesDelegate - .customerInfo? - .entitlements[Self.entitlementIdentifier] - - return entitlement?.isActive == true - }, + description: "Entitlement didn't become active", timeout: .seconds(5), - pollInterval: .milliseconds(500), - description: "Entitlement didn't become active" - ) + pollInterval: .milliseconds(500) + ) { + let entitlement = await self.purchasesDelegate + .customerInfo? + .entitlements[Self.entitlementIdentifier] + + return entitlement?.isActive == true + } } @available(iOS 15.0, tvOS 15.0, watchOS 8.0, macOS 12.0, *) @@ -101,13 +100,12 @@ class StoreKit1ObserverModeIntegrationTests: BaseStoreKitObserverModeIntegration try self.testSession.buyProduct(productIdentifier: Self.monthlyNoIntroProductID) try await asyncWait( - until: { - await self.purchasesDelegate.customerInfo?.entitlements.active.isEmpty == false - }, + description: "Delegate should be notified", timeout: .seconds(4), - pollInterval: .milliseconds(100), - description: "Delegate should be notified" - ) + pollInterval: .milliseconds(100) + ) { + await self.purchasesDelegate.customerInfo?.entitlements.active.isEmpty == false + } let customerInfo = try XCTUnwrap(self.purchasesDelegate.customerInfo) try await self.verifyEntitlementWentThrough(customerInfo) diff --git a/Tests/StoreKitUnitTests/StoreKit2/StoreKit2TransactionListenerTests.swift b/Tests/StoreKitUnitTests/StoreKit2/StoreKit2TransactionListenerTests.swift index e953569560..429402e4e1 100644 --- a/Tests/StoreKitUnitTests/StoreKit2/StoreKit2TransactionListenerTests.swift +++ b/Tests/StoreKitUnitTests/StoreKit2/StoreKit2TransactionListenerTests.swift @@ -315,13 +315,14 @@ private extension StoreKit2TransactionListenerBaseTests { line: UInt = #line ) async throws { try await asyncWait( - until: { await self.delegate.invokedTransactionUpdated == true }, + description: "Transaction update", timeout: .seconds(4), pollInterval: .milliseconds(100), - description: "Transaction update", file: file, line: line - ) + ) { + await self.delegate.invokedTransactionUpdated == true + } } } diff --git a/Tests/StoreKitUnitTests/TestHelpers/StoreKitConfigTestCase+Extensions.swift b/Tests/StoreKitUnitTests/TestHelpers/StoreKitConfigTestCase+Extensions.swift index 7b15782f3c..35c207d99a 100644 --- a/Tests/StoreKitUnitTests/TestHelpers/StoreKitConfigTestCase+Extensions.swift +++ b/Tests/StoreKitUnitTests/TestHelpers/StoreKitConfigTestCase+Extensions.swift @@ -96,11 +96,12 @@ extension StoreKitConfigTestCase { self.testSession.storefront = new try await asyncWait( - until: { await Storefront.currentStorefront?.countryCode == new }, + description: "Storefront change not detected", timeout: .seconds(1), - pollInterval: .milliseconds(100), - description: "Storefront change not detected" - ) + pollInterval: .milliseconds(100) + ) { + await Storefront.currentStorefront?.countryCode == new + } } } diff --git a/Tests/UnitTests/Identity/CustomerInfoManagerPostReceiptTests.swift b/Tests/UnitTests/Identity/CustomerInfoManagerPostReceiptTests.swift index ecd01d2fac..093c7cacb2 100644 --- a/Tests/UnitTests/Identity/CustomerInfoManagerPostReceiptTests.swift +++ b/Tests/UnitTests/Identity/CustomerInfoManagerPostReceiptTests.swift @@ -82,9 +82,10 @@ class CustomerInfoManagerPostReceiptTests: BaseCustomerInfoManagerTests { expect(parameters.data.source.initiationSource) == .queue } - func testPostsAllTransactions() async throws { + func testPostsFirstTransaction() async throws { + let transactionToPost = Self.createTransaction() let transactions = [ - Self.createTransaction(), + transactionToPost, Self.createTransaction(), Self.createTransaction() ] @@ -96,21 +97,25 @@ class CustomerInfoManagerPostReceiptTests: BaseCustomerInfoManagerTests { isAppBackgrounded: false) expect(self.mockBackend.invokedGetSubscriberData) == false expect(self.mockTransactionPoster.invokedHandlePurchasedTransaction.value) == true - expect(self.mockTransactionPoster.invokedHandlePurchasedTransactionCount.value) == transactions.count - expect( - self.mockTransactionPoster.invokedHandlePurchasedTransactionParameterList.value - .map(\.transaction) - .compactMap { $0 as? StoreTransaction } - ) - == transactions + // The first transaction is posted synchronously. + // The rest are posted in the background. + expect(self.mockTransactionPoster.invokedHandlePurchasedTransactionCount.value) >= 1 + + expect(self.mockTransactionPoster.allHandledTransactions).to(contain(transactionToPost)) self.logger.verifyMessageWasLogged( Strings.customerInfo.posting_transactions_in_lieu_of_fetching_customerinfo(transactions), level: .debug ) + + try await asyncWait( + description: "The rest of transactions should be posted asynchronously" + ) { [poster = self.mockTransactionPoster!] in + poster.allHandledTransactions == Set(transactions) + } } - func testPostingAllTransactionsReturnsLastKnownSuccess() async throws { + func testPostingAllTransactionsReturnsFirstResult() async throws { let otherMockCustomerInfo = try CustomerInfo(data: [ "request_date": "2024-12-21T02:40:36Z", "subscriber": [ @@ -135,22 +140,21 @@ class CustomerInfoManagerPostReceiptTests: BaseCustomerInfoManagerTests { .failure(.networkError(.serverDown())) ] - _ = try await self.customerInfoManager.fetchAndCacheCustomerInfo(appUserID: Self.userID, - isAppBackgrounded: false) + let result = try await self.customerInfoManager.fetchAndCacheCustomerInfo(appUserID: Self.userID, + isAppBackgrounded: false) + expect(result) === otherMockCustomerInfo + expect(self.mockBackend.invokedGetSubscriberData) == false expect(self.mockTransactionPoster.invokedHandlePurchasedTransaction.value) == true - expect(self.mockTransactionPoster.invokedHandlePurchasedTransactionCount.value) == transactions.count - expect( - self.mockTransactionPoster.invokedHandlePurchasedTransactionParameterList.value - .map(\.transaction) - .compactMap { $0 as? StoreTransaction } - ) - == transactions self.logger.verifyMessageWasLogged( Strings.customerInfo.posting_transactions_in_lieu_of_fetching_customerinfo(transactions), level: .debug ) + + try await asyncWait { [poster = self.mockTransactionPoster!] in + poster.allHandledTransactions == Set(transactions) + } } } diff --git a/Tests/UnitTests/Mocks/MockTransactionPoster.swift b/Tests/UnitTests/Mocks/MockTransactionPoster.swift index 7c1ecff068..863a4e09a0 100644 --- a/Tests/UnitTests/Mocks/MockTransactionPoster.swift +++ b/Tests/UnitTests/Mocks/MockTransactionPoster.swift @@ -30,6 +30,15 @@ final class MockTransactionPoster: TransactionPosterType { let invokedHandlePurchasedTransactionParameterList: Atomic<[(transaction: StoreTransactionType, data: PurchasedTransactionData)]> = .init([]) + var allHandledTransactions: Set { + return Set( + self + .invokedHandlePurchasedTransactionParameterList.value + .map(\.transaction) + .compactMap { $0 as? StoreTransaction } + ) + } + func handlePurchasedTransaction( _ transaction: StoreTransactionType, data: PurchasedTransactionData, @@ -43,9 +52,11 @@ final class MockTransactionPoster: TransactionPosterType { } self.invokedHandlePurchasedTransaction.value = true - self.invokedHandlePurchasedTransactionCount.value += 1 + self.invokedHandlePurchasedTransactionCount.modify { $0 += 1 } self.invokedHandlePurchasedTransactionParameters.value = (transaction, data) - self.invokedHandlePurchasedTransactionParameterList.value.append((transaction, data)) + self.invokedHandlePurchasedTransactionParameterList.modify { + $0.append((transaction, data)) + } self.operationDispatcher.dispatchOnMainActor { [result = result()] in completion(result) diff --git a/Tests/UnitTests/TestHelpers/AsyncTestHelpers.swift b/Tests/UnitTests/TestHelpers/AsyncTestHelpers.swift index f4d554b52d..008ad02e1b 100644 --- a/Tests/UnitTests/TestHelpers/AsyncTestHelpers.swift +++ b/Tests/UnitTests/TestHelpers/AsyncTestHelpers.swift @@ -66,12 +66,12 @@ func waitUntilValue( // Fix-me: remove once we can use Quick v6.x: @available(iOS 13.0, macOS 10.15, tvOS 13.0, watchOS 6.2, *) func asyncWait( - until condition: @Sendable () async -> Bool, + description: String? = nil, timeout: DispatchTimeInterval = defaultTimeout, pollInterval: DispatchTimeInterval = defaultPollInterval, - description: String? = nil, file: FileString = #fileID, - line: UInt = #line + line: UInt = #line, + until condition: @Sendable () async -> Bool ) async throws { let start = Date() var foundCorrectValue = false diff --git a/Tests/UnitTests/TestHelpers/TestLogHandler.swift b/Tests/UnitTests/TestHelpers/TestLogHandler.swift index 830e51b253..74377de8cb 100644 --- a/Tests/UnitTests/TestHelpers/TestLogHandler.swift +++ b/Tests/UnitTests/TestHelpers/TestLogHandler.swift @@ -86,6 +86,8 @@ extension TestLogHandler: Sendable {} extension TestLogHandler { + private typealias EntryCondition = @Sendable (MessageData) -> Bool + /// Useful if you want to ignore messages logged so far. func clearMessages() { self.loggedMessages.value.removeAll(keepingCapacity: false) @@ -116,7 +118,7 @@ extension TestLogHandler { expect( file: file, line: line, - self.messages.lazy.filter(condition).count + self.messagesMatching(condition) ) .to( equal(expectedCount), @@ -129,6 +131,7 @@ extension TestLogHandler { func verifyMessageIsEventuallyLogged( _ message: String, level: LogLevel? = nil, + expectedCount: Int? = nil, timeout: DispatchTimeInterval = AsyncDefaults.timeout, pollInterval: DispatchTimeInterval = AsyncDefaults.pollInterval, file: FileString = #file, @@ -137,12 +140,26 @@ extension TestLogHandler { let condition = Self.entryCondition(message: message, level: level) try await asyncWait( - until: { self.messages.contains(where: condition) }, - timeout: timeout, pollInterval: pollInterval, description: "Message '\(message)' not found. Logged messages: \(self.messages)", + timeout: timeout, + pollInterval: pollInterval, file: file, line: line - ) + ) { + self.messages.contains(where: condition) + } + + if let expectedCount = expectedCount { + try await asyncWait( + description: "Message '\(message)' expected \(expectedCount) times", + timeout: timeout, + pollInterval: pollInterval, + file: file, + line: line + ) { + self.messagesMatching(condition) == expectedCount + } + } } /// - Parameter allowNoMessages: by default, this method requires logs to not be empty @@ -178,9 +195,17 @@ extension TestLogHandler { ) } + private func messagesMatching(_ condition: EntryCondition) -> Int { + return self + .messages + .lazy + .filter(condition) + .count + } + private static func entryCondition( message: CustomStringConvertible, level: LogLevel? - ) -> @Sendable (MessageData) -> Bool { + ) -> EntryCondition { return { entry in guard entry.message.contains(message.description) else { return false