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.

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(

Sources/Identity/CustomerInfoManager.swift

@@ -321,35 +321,33 @@ private extension CustomerInfoManager {
             _ = Task<Void, Never> {
                 let transactions = await self.transactionFetcher.unfinishedVerifiedTransactions
 
-                if !transactions.isEmpty {
-                    var results: [Result<CustomerInfo, BackendError>] = []
-                    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,

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)"

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)"
 

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 }

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)
     }
 
 }

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)

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
+        }
     }
 
 }

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
+        }
     }
 
 }

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)
+        }
     }
 
 }

Tests/UnitTests/Mocks/MockTransactionPoster.swift

@@ -30,6 +30,15 @@ final class MockTransactionPoster: TransactionPosterType {
     let invokedHandlePurchasedTransactionParameterList: Atomic<[(transaction: StoreTransactionType,
                                                                  data: PurchasedTransactionData)]> = .init([])
 
+    var allHandledTransactions: Set<StoreTransaction> {
+        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)