Main Thread Locking

[tristan-warner-smith]

• I have updated Purchases SDK to the latest version
• I have read the Contribution Guidelines
• I have searched the Community
• I have read docs.revenuecat.com
• I have searched for existing Github issues

Describe the bug
We're experiencing somewhat regular main thread hangs that appear to be related to lock usage in the SDK.
Attaching images below.

1. Environment
   1. Platform: iOS
   2. SDK version: 5.2.2
   3. StoreKit version:
      • StoreKit 1
      • StoreKit 2 (enabled with usesStoreKit2IfAvailable(true))
   4. OS version: 17.5
   5. Xcode version: 15.4
   6. Device and/or simulator:
      • Device
      • Simulator
   7. Environment:
      • Sandbox
      • TestFlight
      • Production
   8. How widespread is the issue. Percentage of devices affected. ~20% of app runs.
2. Debug logs that reproduce the issue. Complete logs with Purchases.logLevel = .verbose will help us debug this issue.

VERBOSE: DeviceCache.init: DeviceCache (0x0000000117e35570)
VERBOSE: Initializing PaywallEventStore: file:///Users/.../Library/Developer/CoreSimulator/Devices/93F00F5D-1682-4CFA-A69B-81B6FFBEBE4D/data/Containers/Data/Application/96049B6C-F3ED-4A2D-B691-346709938D30/Library/Application%20Support/revenuecat/paywall_event_store
VERBOSE: Creating FileHandler for: file:///Users/.../Library/Developer/CoreSimulator/Devices/93F00F5D-1682-4CFA-A69B-81B6FFBEBE4D/data/Containers/Data/Application/96049B6C-F3ED-4A2D-B691-346709938D30/Library/Application%20Support/revenuecat/paywall_event_store
VERBOSE: PaywallEventsManager initialized
VERBOSE: PurchasesOrchestrator.init: PurchasesOrchestrator (0x0000000118da4b80)
VERBOSE: Purchases.init: created new Purchases instance: Purchases (0x0000000117d06840)
StoreKit Wrapper: right(<RevenueCat.PaymentQueueWrapper: 0x116444590>)
VERBOSE: Updating all caches
VERBOSE: Enqueing network operation 'GetOfferingsOperation' with cache key: 'GetOfferingsOperation a63afqRdLahuvUoUmxgMrsAEOSm2'
VERBOSE: Enqueing network operation 'GetCustomerInfoOperation' with cache key: 'GetCustomerInfoOperation a63afqRdLahuvUoUmxgMrsAEOSm2'
VERBOSE: Using etag 'c237e42911476e3c' for request to 'https://api.revenuecat.com/v1/subscribers/a63afqRdLahuvUoUmxgMrsAEOSm2/offerings'. Validation time: 2024-07-30 20:55:14 +0000
VERBOSE: Storing etag 'c237e42911476e3c' for request to 'https://api.revenuecat.com/v1/subscribers/a63afqRdLahuvUoUmxgMrsAEOSm2/offerings' (success)
VERBOSE: Using etag '1d31eb8debb9281a' for request to 'https://api.revenuecat.com/v1/subscribers/a63afqRdLahuvUoUmxgMrsAEOSm2'. Validation time: 2024-07-30 20:55:12 +0000
VERBOSE: Storing etag '1d31eb8debb9281a' for request to 'https://api.revenuecat.com/v1/subscribers/a63afqRdLahuvUoUmxgMrsAEOSm2' (success)

3. Steps to reproduce, with a description of expected vs. actual behavior
   Swift UI project targeting iOS 16+.
   The SDK is configured within the scope of the App's init:

@main
struct App {
    init() {
        self._viewModel = StateObject(wrappedValue: AppViewModel(appRouter: router))
    }
}

The SDK is initialised in a Task of the ViewModel's initialiser. The init is executed on the MainActor as it's called from the App, so the SDK call to Purchases.configure(withAPIKey: apiKey, appUserID: nil) will be using that parent scope.

5. Other information (e.g. stacktraces, related issues, suggestions how to fix, links for us to have context, eg. stackoverflow, etc.)
   There's what could be related PR open although the console says "Purchases is configured with StoreKit version 2"
   
   

6. Additional context
   Add any other context about the problem here.

[RCGitBot]

👀 We've just linked this issue to our internal tracker and notified the team. Thank you for reporting, we're checking this out!

[aboedo]

@tristan-warner-smith thanks for reporting! It does feel related to the bug that @joshdholtz's PR fixes, despite the console output, since we get the storefront through SK1 even if SK2 is enabled

[tristan-warner-smith]

@aboedo I've tried out @joshdholtz's PR and it did make a difference but unfortunately didn't go far enough.
Here's where it's locking subsequently:

And here's a crash log we got with it:
crashlog.txt

[jesus-mg-ios]

Reproduced ... seems that there's a lock in synchronizedUserDefaults because it uses any kinda lock there and write waits for a read. @aboedo @nyeu any fix ETA?

[nguyenhuy]

Here is a test case that can reliably reproduce this deadlock:

func testDeadlock() {
    NotificationCenter.default.addObserver(forName: UserDefaults.didChangeNotification,
                                           object: nil,
                                           queue: OperationQueue.main) { _ in }

    let userDefaults = SynchronizedUserDefaults(userDefaults: UserDefaults.standard)

    DispatchQueue.global(qos: .userInteractive).async { [userDefaults] in
        userDefaults.write {
            $0.set("value", forKey: "key")
        }
    }

    // Suspend main thread to give the above background write operation time
    // to perform and trigger a did change notification on the main queue
    Thread.sleep(forTimeInterval: 0.5)

    _ = userDefaults.read {
        $0.string(forKey: "key")
    }
}

The deadlock occurs when:

• Main thread tries to grab SynchronizedUserDefaults's lock.
• A background thread that is holding that lock posts a notification onto main thread and decides to wait for that to finish before proceeding. This is quite clear when you look at the below frames taken from @tristan-warner-smith's crashlog.txt:

Thread 1::  Dispatch queue: com.apple.NSURLSession-delegate
0   libsystem_kernel.dylib        	       0x112ec4a70 __psynch_cvwait + 8
1   libsystem_pthread.dylib       	       0x112feb9cc _pthread_cond_wait + 1216
2   Foundation                    	       0x180d9d1f8 -[NSOperation waitUntilFinished] + 504
3   CoreFoundation                	       0x1803dd5d8 _CFXNotificationPost + 752
4   Foundation                    	       0x180d8aa14 -[NSNotificationCenter postNotificationName:object:userInfo:] + 88
...
7                           	               0x107698dd0 closure #1 in SynchronizedUserDefaults.write(_:) + 716 (SynchronizedUserDefaults.swift:35)

From frame 7, the notification is either:

• A UserDefaults.didChangeNotification for which a block was registered to be executed on the main queue (see the test case).
• One of other UserDefaults's notifications that are always posted on the main queue.

Generally speaking, it is not a good idea for an object (A) to call another object (B) (like a delegate) or execute a provided block (usuaslly a callback/completion block) while holding its lock. Since A doesn't know nor control what B or the block will do, it essentially exposes its lock to those outsiders and loses control over it. It opens the door for deadlocks like this.

To retain control, A should almost always release its lock before calling out. And this is probably what UserDefaults does internally with its own pthread_mutex. Yes, the class is thread-safe. And when I modified my test case to test UserDefaults, it didn't deadlock.

This leads to my main questions: Why do we need SynchronizedUserDefaults? Why can't this SDK just use UserDefaults?

After briefly looking at usages of SynchronizedUserDefaults, I think most can simply be replaced by UserDefaults, for example in ETagManager. The only heavy user of SynchronizedUserDefaults that needs a closer look is DeviceCache.

[nguyenhuy]

Here is the stack trace when my test deadlocks: