Performance: throttle cache updates, and avoid double updates on ap…

…p launch

Possibly as a consequence of #2623 we were calling `updateAllCachesIfNeeded` on app launch together with `updateCachesIfInForeground`, meaning that we were updating all caches twice.
Thanks to our de-duping logic this is normally not a big issue, but this issue combined with what #2954 fixes, means that if there are pending transactions, opening the app would probably end up posting receipts duplicated times.

This adds a new log as well to detect this:
> [purchases] DEBUG: ℹ️ Throttling cache update, only 0.8 seconds elapsed

And a new integration test that posts `UIApplication.willEnterForegroundNotification` to test this.

RevenueCat.xcodeproj/project.pbxproj

@@ -237,6 +237,7 @@
 		4F6BEE3C2A27B45900CD9322 /* Constants.swift in Sources */ = {isa = PBXBuildFile; fileRef = 2DE61A83264190830021CEA0 /* Constants.swift */; };
 		4F6BEE882A27E16B00CD9322 /* TestLogHandler.swift in Sources */ = {isa = PBXBuildFile; fileRef = 57057FF728B0048900995F21 /* TestLogHandler.swift */; };
 		4F6E81E62A82AAE1006EF181 /* HTTPRequestPath.swift in Sources */ = {isa = PBXBuildFile; fileRef = 4F6E81E52A82AAE1006EF181 /* HTTPRequestPath.swift */; };
+		4F6E81982A81BC30006EF181 /* TestClock.swift in Sources */ = {isa = PBXBuildFile; fileRef = 578DAA492948EF4F001700FD /* TestClock.swift */; };
 		4F6EEBD92A38ED76007FD783 /* FakeSigning.swift in Sources */ = {isa = PBXBuildFile; fileRef = 4F6EEBD82A38ED76007FD783 /* FakeSigning.swift */; };
 		4F7C37B22A27E2E8001E17D3 /* AsyncTestHelpers.swift in Sources */ = {isa = PBXBuildFile; fileRef = 575A8EE02922C56300936709 /* AsyncTestHelpers.swift */; };
 		4F7C37E42A27EFE1001E17D3 /* BaseBackendIntegrationTests.swift in Sources */ = {isa = PBXBuildFile; fileRef = 579234E127F777EE00B39C68 /* BaseBackendIntegrationTests.swift */; };
@@ -3139,6 +3140,7 @@
 				4FA4C9752A16D49E007D2803 /* MockOfflineEntitlementsManager.swift in Sources */,
 				F5E5E2EE28479BD000216ECD /* ProductsFetcherSK2Tests.swift in Sources */,
 				3543913626F90D6A00E669DF /* TrialOrIntroPriceEligibilityCheckerSK1Tests.swift in Sources */,
+				4F6E81982A81BC30006EF181 /* TestClock.swift in Sources */,
 				2D34D9D227481D9B00C05DB6 /* TrialOrIntroPriceEligibilityCheckerSK2Tests.swift in Sources */,
 				2D90F8C726FD221D009B9142 /* MockASN1ContainerBuilder.swift in Sources */,
 				F535515F286B5BE5009CA47A /* MockOfferingsManager.swift in Sources */,

Sources/Logging/Strings/PurchaseStrings.swift

@@ -26,6 +26,7 @@ enum PurchaseStrings {
     case purchases_orchestrator_init(PurchasesOrchestrator)
     case purchases_orchestrator_deinit(PurchasesOrchestrator)
     case updating_all_caches
+    case throttling_cache_update(TimeInterval)
     case not_updating_caches_while_products_are_in_progress
     case cannot_purchase_product_appstore_configuration_error
     case entitlements_revoked_syncing_purchases(productIdentifiers: [String])
@@ -110,6 +111,9 @@ extension PurchaseStrings: LogMessage {
         case .updating_all_caches:
             return "Updating all caches"
 
+        case let .throttling_cache_update(timeInterval):
+            return String(format: "Throttling cache update, only %.1f seconds elapsed", timeInterval)
+
         case .not_updating_caches_while_products_are_in_progress:
             return "Detected purchase in progress: will skip cache updates"
 

Sources/Misc/DateAndTime/Clock.swift

@@ -30,3 +30,15 @@ final class Clock: ClockType {
     static let `default`: Clock = .init()
 
 }
+
+extension ClockType {
+
+    func durationSince(_ startTime: DispatchTime) -> TimeInterval {
+        if #available(iOS 13.0, macOS 10.15, tvOS 13.0, watchOS 6.2, *) {
+            return startTime.distance(to: self.currentTime).seconds
+        } else {
+            return TimeInterval(self.currentTime.uptimeNanoseconds - startTime.uptimeNanoseconds) / 1_000_000_000
+        }
+    }
+
+}

Sources/Misc/DateAndTime/TimingUtil.swift

@@ -314,15 +314,3 @@ private extension TimingUtil {
     }
 
 }
-
-private extension ClockType {
-
-    func durationSince(_ startTime: DispatchTime) -> TimingUtil.Duration {
-        if #available(iOS 13.0, macOS 10.15, tvOS 13.0, watchOS 6.2, *) {
-            return startTime.distance(to: self.currentTime).seconds
-        } else {
-            return TimingUtil.Duration(self.currentTime.uptimeNanoseconds - startTime.uptimeNanoseconds) / 1_000_000_000
-        }
-    }
-
-}

Sources/Misc/SystemInfo.swift

@@ -34,6 +34,7 @@ class SystemInfo {
     let platformFlavorVersion: String?
     let responseVerificationMode: Signing.ResponseVerificationMode
     let dangerousSettings: DangerousSettings
+    let clock: ClockType
 
     var finishTransactions: Bool {
         get { return self._finishTransactions.value }
@@ -76,6 +77,9 @@ class SystemInfo {
         return Self.forceUniversalAppStore ? "iOS" : self.platformHeaderConstant
     }
 
+    /// Caches won't be updated when foregrounding the app multiple times faster than this duration
+    static let cacheUpdateThrottleDuration: DispatchTimeInterval = .seconds(10)
+
     var identifierForVendor: String? {
         // Should match available platforms in
         // https://developer.apple.com/documentation/uikit/uidevice?language=swift
@@ -107,7 +111,8 @@ class SystemInfo {
          sandboxEnvironmentDetector: SandboxEnvironmentDetector = BundleSandboxEnvironmentDetector.default,
          storeKit2Setting: StoreKit2Setting = .default,
          responseVerificationMode: Signing.ResponseVerificationMode = .default,
-         dangerousSettings: DangerousSettings? = nil) {
+         dangerousSettings: DangerousSettings? = nil,
+         clock: ClockType = Clock.default) {
         self.platformFlavor = platformInfo?.flavor ?? "native"
         self.platformFlavorVersion = platformInfo?.version
         self._bundle = .init(bundle)
@@ -118,6 +123,7 @@ class SystemInfo {
         self.sandboxEnvironmentDetector = sandboxEnvironmentDetector
         self.responseVerificationMode = responseVerificationMode
         self.dangerousSettings = dangerousSettings ?? DangerousSettings()
+        self.clock = clock
     }
 
     /// Asynchronous API if caller can't ensure that it's invoked in the `@MainActor`

Sources/Networking/Backend.swift

@@ -36,7 +36,7 @@ class Backend {
         let httpClient = HTTPClient(apiKey: apiKey,
                                     systemInfo: systemInfo,
                                     eTagManager: eTagManager,
-                                    signing: Signing(apiKey: apiKey),
+                                    signing: Signing(apiKey: apiKey, clock: systemInfo.clock),
                                     requestTimeout: httpClientTimeout)
         let config = BackendConfiguration(httpClient: httpClient,
                                           operationDispatcher: operationDispatcher,

Sources/Purchasing/Purchases/Purchases.swift

@@ -233,6 +233,8 @@ public typealias StartPurchaseBlock = (@escaping PurchaseCompletedBlock) -> Void
         set { self.systemInfo.finishTransactions = newValue }
     }
 
+    private let lastCacheUpdateTime: Atomic<DispatchTime?> = nil
+
     private let attributionFetcher: AttributionFetcher
     private let attributionPoster: AttributionPoster
     private let backend: Backend
@@ -1487,10 +1489,13 @@ private extension Purchases {
     @objc func applicationWillEnterForeground() {
         Logger.debug(Strings.configure.application_foregrounded)
 
+        guard !self.shouldSkipCacheUpdate() else { return }
+
         // Note: it's important that we observe "will enter foreground" instead of
         // "did become active" so that we don't trigger cache updates in the middle
         // of purchases due to pop-ups stealing focus from the app.
         self.updateAllCachesIfNeeded(isAppBackgrounded: false)
+        self.setLastCacheUpdateTime()
         self.dispatchSyncSubscriberAttributes()
 
         #if !ENABLE_CUSTOM_ENTITLEMENT_COMPUTATION
@@ -1535,6 +1540,8 @@ private extension Purchases {
                 self.operationDispatcher.dispatchOnWorkerThread {
                     self.updateAllCaches(isAppBackgrounded: isBackgrounded, completion: nil)
                 }
+
+                self.setLastCacheUpdateTime()
             }
         }
     }
@@ -1603,6 +1610,23 @@ private extension Purchases {
                                                    completion: nil)
     }
 
+    func shouldSkipCacheUpdate() -> Bool {
+        guard let lastUpdate = self.lastCacheUpdateTime.value else { return false }
+
+        let interval = self.systemInfo.clock.durationSince(lastUpdate)
+        let shouldSkip = interval <= SystemInfo.cacheUpdateThrottleDuration.seconds
+
+        if shouldSkip {
+            Logger.debug(Strings.purchase.throttling_cache_update(interval))
+        }
+
+        return shouldSkip
+    }
+
+    func setLastCacheUpdateTime() {
+        self.lastCacheUpdateTime.value = .now()
+    }
+
 }
 
 // MARK: - Deprecations

Sources/Purchasing/ReceiptFetcher.swift

@@ -19,7 +19,6 @@ class ReceiptFetcher {
     private let requestFetcher: StoreKitRequestFetcher
     private let receiptParser: PurchasesReceiptParser
     private let fileReader: FileReader
-    private let clock: ClockType
 
     private let lastReceiptRefreshRequest: Atomic<Date?> = nil
 
@@ -29,14 +28,12 @@ class ReceiptFetcher {
         requestFetcher: StoreKitRequestFetcher,
         systemInfo: SystemInfo,
         receiptParser: PurchasesReceiptParser = .default,
-        fileReader: FileReader = DefaultFileReader(),
-        clock: ClockType = Clock.default
+        fileReader: FileReader = DefaultFileReader()
     ) {
         self.requestFetcher = requestFetcher
         self.systemInfo = systemInfo
         self.receiptParser = receiptParser
         self.fileReader = fileReader
-        self.clock = clock
     }
 
     func receiptData(refreshPolicy: ReceiptRefreshPolicy, completion: @escaping (Data?, URL?) -> Void) {
@@ -97,7 +94,7 @@ class ReceiptFetcher {
             return false
         }
 
-        let timeSinceLastRequest = DispatchTimeInterval(self.clock.now.timeIntervalSince(lastRefresh))
+        let timeSinceLastRequest = DispatchTimeInterval(self.systemInfo.clock.now.timeIntervalSince(lastRefresh))
         return timeSinceLastRequest < ReceiptRefreshPolicy.alwaysRefreshThrottleDuration
     }
 
@@ -155,7 +152,7 @@ private extension ReceiptFetcher {
     }
 
     func refreshReceipt(_ completion: @escaping (Data, URL?) -> Void) {
-        self.lastReceiptRefreshRequest.value = self.clock.now
+        self.lastReceiptRefreshRequest.value = self.systemInfo.clock.now
 
         self.requestFetcher.fetchReceiptData {
             completion(self.receiptData() ?? Data(), self.receiptURL)

Tests/BackendIntegrationTests/OtherIntegrationTests.swift

@@ -111,4 +111,16 @@ class OtherIntegrationTests: BaseBackendIntegrationTests {
         )
     }
 
+    func testCustomerInfoIsOnlyFetchedOnceOnAppLaunch() async throws {
+        try await self.logger.verifyMessageIsEventuallyLogged("GetCustomerInfoOperation: Finished")
+
+        self.logger.clearMessages()
+
+        // This notification is posted automatically on app launch
+        NotificationCenter.default.post(name: SystemInfo.applicationWillEnterForegroundNotification,
+                                        object: nil)
+
+        try await self.logger.verifyMessageIsEventuallyLogged("Throttling cache update", level: .debug)
+    }
+
 }

Tests/UnitTests/Mocks/MockSystemInfo.swift

@@ -18,12 +18,14 @@ class MockSystemInfo: SystemInfo {
 
     convenience init(finishTransactions: Bool,
                      storeKit2Setting: StoreKit2Setting = .default,
-                     customEntitlementsComputation: Bool = false) {
+                     customEntitlementsComputation: Bool = false,
+                     clock: ClockType = TestClock()) {
         let dangerousSettings = DangerousSettings(customEntitlementComputation: customEntitlementsComputation)
         self.init(platformInfo: nil,
                   finishTransactions: finishTransactions,
                   storeKit2Setting: storeKit2Setting,
-                  dangerousSettings: dangerousSettings)
+                  dangerousSettings: dangerousSettings,
+                  clock: clock)
     }
 
     override func isApplicationBackgrounded(completion: @escaping (Bool) -> Void) {

Tests/UnitTests/Purchasing/Purchases/BasePurchasesTests.swift

@@ -37,7 +37,10 @@ class BasePurchasesTests: TestCase {
         self.mockPaymentQueueWrapper = MockPaymentQueueWrapper()
 
         self.userDefaults = UserDefaults(suiteName: Self.userDefaultsSuiteName)
-        self.systemInfo = MockSystemInfo(finishTransactions: true, storeKit2Setting: self.storeKit2Setting)
+        self.clock = TestClock()
+        self.systemInfo = MockSystemInfo(finishTransactions: true,
+                                         storeKit2Setting: self.storeKit2Setting,
+                                         clock: self.clock)
         self.deviceCache = MockDeviceCache(sandboxEnvironmentDetector: self.systemInfo,
                                            userDefaults: self.userDefaults)
         self.requestFetcher = MockRequestFetcher()
@@ -142,6 +145,7 @@ class BasePurchasesTests: TestCase {
     var subscriberAttributesManager: MockSubscriberAttributesManager!
     var attribution: Attribution!
     var identityManager: MockIdentityManager!
+    var clock: TestClock!
     var systemInfo: MockSystemInfo!
     var mockOperationDispatcher: MockOperationDispatcher!
     var mockIntroEligibilityCalculator: MockIntroEligibilityCalculator!
@@ -203,7 +207,8 @@ class BasePurchasesTests: TestCase {
     func setUpPurchasesObserverModeOn() {
         self.systemInfo = MockSystemInfo(platformInfo: nil,
                                          finishTransactions: false,
-                                         storeKit2Setting: self.storeKit2Setting)
+                                         storeKit2Setting: self.storeKit2Setting,
+                                         clock: self.clock)
         self.initializePurchasesInstance(appUserId: nil)
     }
 

Tests/UnitTests/Purchasing/Purchases/PurchasesDelegateTests.swift

@@ -60,22 +60,47 @@ class PurchasesDelegateTests: BasePurchasesTests {
         expect(self.backend.userID).toEventuallyNot(beNil())
     }
 
-    func testAutomaticallyFetchesCustomerInfoOnDidBecomeActiveIfCacheStale() {
+    func testAutomaticallyFetchesCustomerInfoOnWillEnterForegroundIfCacheStale() {
         expect(self.backend.getCustomerInfoCallCount).toEventually(equal(1))
 
         self.deviceCache.stubbedIsCustomerInfoCacheStale = true
+        self.clock.advance(by: SystemInfo.cacheUpdateThrottleDuration + .seconds(1))
+
         self.notificationCenter.fireNotifications()
 
         expect(self.backend.getCustomerInfoCallCount).toEventually(equal(2))
     }
 
-    func testDoesntAutomaticallyFetchCustomerInfoOnDidBecomeActiveIfCacheValid() {
+    func testDoesntAutomaticallyFetchCustomerInfoOnWillEnterForegroundIfCacheValid() {
         expect(self.backend.getCustomerInfoCallCount).toEventually(equal(1))
         self.deviceCache.stubbedIsCustomerInfoCacheStale = false
 
         self.notificationCenter.fireNotifications()
 
+        expect(self.backend.getCustomerInfoCallCount) == 1
+    }
+
+    func testDoesNotFetchCustomerInfoTwiceOnAppLaunch() {
+        self.deviceCache.stubbedIsCustomerInfoCacheStale = true
+
         expect(self.backend.getCustomerInfoCallCount).toEventually(equal(1))
+
+        self.notificationCenter.fireNotifications()
+        expect(self.backend.getCustomerInfoCallCount) == 1
+        expect(self.deviceCache.cachedCustomerInfoCount) == 1
+    }
+
+    func testForegroundingAppMultipleTimesDoesNotFetchCustomerInfoRepeteadly() {
+        self.deviceCache.stubbedIsCustomerInfoCacheStale = true
+
+        expect(self.backend.getCustomerInfoCallCount).toEventually(equal(1))
+
+        for _ in 0..<10 {
+            self.notificationCenter.fireNotifications()
+        }
+
+        expect(self.backend.getCustomerInfoCallCount) == 1
+        expect(self.deviceCache.cachedCustomerInfoCount) == 1
     }
 
     func testAutomaticallyCallsDelegateOnDidBecomeActiveAndUpdate() {

Tests/UnitTests/Purchasing/Purchases/PurchasesGetOfferingsTests.swift

@@ -50,6 +50,39 @@ class PurchasesGetOfferingsTests: BasePurchasesTests {
         expect(self.mockOfflineEntitlementsManager.invokedUpdateProductsEntitlementsCacheIfStale) == false
     }
 
+    func testForegroundingAppUpdatesOfferingsIfCacheIsStale() {
+        self.setupPurchases()
+
+        expect(self.mockOfferingsManager.invokedUpdateOfferingsCacheCount) == 1
+
+        self.deviceCache.stubbedIsOfferingsCacheStale = true
+        self.clock.advance(by: SystemInfo.cacheUpdateThrottleDuration + .seconds(1))
+
+        self.notificationCenter.fireNotifications()
+
+        expect(self.mockOfferingsManager.invokedUpdateOfferingsCacheCount) == 2
+    }
+
+    func testForegroundingAppDoesNotUpdateOfferingsIfCacheIsNotStale() {
+        self.setupPurchases()
+
+        self.deviceCache.stubbedIsOfferingsCacheStale = false
+        self.notificationCenter.fireNotifications()
+
+        expect(self.mockOfferingsManager.invokedUpdateOfferingsCacheCount) == 1
+    }
+
+    func testForegroundingAppMultipleTimesDoesNotFetchOfferingsRepeteadly() {
+        self.setupPurchases()
+        self.deviceCache.stubbedIsOfferingsCacheStale = true
+
+        for _ in 0..<10 {
+            self.notificationCenter.fireNotifications()
+        }
+
+        expect(self.mockOfferingsManager.invokedUpdateOfferingsCacheCount) == 1
+    }
+
     func testProductDataIsCachedForOfferings() throws {
         self.setupPurchases()
 

Tests/UnitTests/Purchasing/ReceiptFetcherTests.swift

@@ -32,16 +32,17 @@ class BaseReceiptFetcherTests: TestCase {
         self.mockBundle = MockBundle()
         self.mockRequestFetcher = MockRequestFetcher()
         self.mockReceiptParser = MockReceiptParser()
+        self.clock = TestClock()
+
         self.mockSystemInfo = MockSystemInfo(platformInfo: nil,
                                              finishTransactions: false,
-                                             bundle: self.mockBundle)
-        self.clock = TestClock()
+                                             bundle: self.mockBundle,
+                                             clock: self.clock)
 
         self.receiptFetcher = ReceiptFetcher(requestFetcher: self.mockRequestFetcher,
                                              systemInfo: self.mockSystemInfo,
                                              receiptParser: self.mockReceiptParser,
-                                             fileReader: self.createFileReader(),
-                                             clock: self.clock)
+                                             fileReader: self.createFileReader())
     }
 
     func createFileReader() -> FileReader {