RevenueCat / purchases-ios

In-app purchases and subscriptions made easy. Support for iOS, watchOS, tvOS, macOS, and visionOS.
https://www.revenuecat.com/
MIT License
2.33k stars 315 forks source link

App Hang in `PostReceiptDataOperation` #2198

Closed swrobel closed 1 year ago

swrobel commented 1 year ago

Creating a new issue per @NachoSoto

Describe the bug I have a React Native app that uses the react-native-purchases library, which I understand depends on this one. One of our testers is seeing frequent app hangs & terminations that all seem to indicate an error with PostReceiptDataOperation. My theory is that this tester has "purchased" our subscription so many times creating test accounts that there is a large volume of transactions to be downloaded that is hanging the app. It's worth noting that this is still happening even after I created a test build that removes all explicit calls to getCustomerInfo(), so this seems to be called when all I'm doing is setting up RevenueCat at app initialization, but not even making any explicit API calls. Removing all RevenueCat code & dependencies from my app prevents the hangs & associated crashes for this tester.

@NachoSoto has proposed that this is a string interpolation issue related to bad data from javascript. I use Purchases.logIn(user.id) from react-native-purchases and my user ids are UUIDs, ex: 4f5d5640-264d-4da2-82ea-ab4d6264f7bc. Or maybe appUserId is something else? I know that the React Native setup instructions don't mention it, though other SDK setup instructions (ie: Swift) do...

  1. Environment
    1. Platform: iOS
    2. SDK versions:
      • react-native: 0.70.6
      • react-native-purchases: 5.4.0
      • PurchasesHybridCommon pod: 4.5.4
      • RevenueCat pod: 4.15.5
    3. StoreKit 2 (disabled with useStoreKit2IfEnabled(false)) (Y/N): N
    4. OS version: 16.1.1
    5. Xcode version: 14
    6. How widespread is the issue. Percentage of devices affected.
  2. Debug logs that reproduce the issue - I can't provide these since it only occurs on a Testflight user's real device
  3. Steps to reproduce, with a description of expected vs. actual behavior
  4. Other information (e.g. stacktraces, related issues, suggestions how to fix, links for us to have context, eg. stackoverflow, etc.)

Additional context Representative crash report (all point to this same series of RevenueCat library calls):

Hardware Model:     iPhone13,2
Process:            Bakesy
Identifier:         app.bakesy.internal
Version:            2.3.6
Role:               Foreground
OS Version:         iOS 16.1.1

App Hang: The app was terminated while unresponsive

0  libsystem_pthread.dylib +0xba8 _thread_chkstk_darwin
1  libswiftCore.dylib +0x232b30   String.UTF8View._foreignSubscript(position:)
2  libswiftCore.dylib +0x2191ac   specialized __StringStorage.appendInPlace<A>(_:isASCII:)
3  libswiftCore.dylib +0x218e00   _StringGuts._foreignAppendInPlace(_:)
4  Bakesy +0x3c82cc               DefaultStringInterpolation.write(_:) (<compiler-generated>)
5  Bakesy +0x3408f0               static PostReceiptDataOperation.createFactory(configuration:postData:customerInfoResponseHandler:customerInfoCallbackCache:) (CustomerInfoResponseHandler.swift)
6  Bakesy +0x3f7678               Backend.post(receiptData:appUserID:isRestore:productData:presentedOfferingIdentifier:observerMode:initiationSource:subscriberAttributes:completion:) (Backend.swift:109:23)
7  Bakesy +0x3fd14c               closure #1 in PurchasesOrchestrator.fetchProductsAndPostReceipt(withTransaction:receiptData:initiationSource:storefront:) (PurchasesOrchestrator.swift:869:22)
8  Bakesy +0x3f17d8               closure #1 in closure #2 in PurchasesOrchestrator.products(withIdentifiers:completion:) (PurchasesOrchestrator.swift:189:17)
9  Bakesy +0x82198                thunk for @escaping @callee_guaranteed () -> () (<compiler-generated>)
10 libdispatch.dylib +0x24b0      __dispatch_call_block_and_release
11 libdispatch.dylib +0x3fd8      __dispatch_client_callout
12 libdispatch.dylib +0x127f0     __dispatch_main_queue_drain
13 libdispatch.dylib +0x12440     __dispatch_main_queue_callback_4CF
14 CoreFoundation +0x9a6f4        ___CFRUNLOOP_IS_SERVICING_THE_MAIN_DISPATCH_QUEUE__
15 CoreFoundation +0x7c054        ___CFRunLoopRun
16 CoreFoundation +0x80ed0        _CFRunLoopRunSpecific
17 GraphicsServices +0x1364       _GSEventRunModal
18 UIKitCore +0x3a23cc            -[UIApplication _run]
19 UIKitCore +0x3a2030            _UIApplicationMain
20 Bakesy +0x6cb8                 main (main.m:8:12)
21 dyld +0x1595c                  start
RCGitBot commented 1 year ago

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

NachoSoto commented 1 year ago

Thanks for the detailed report!

This is coming from here:

let cacheKey =
"""
\(configuration.appUserID)-\(postData.isRestore)-\(postData.receiptData.asFetchToken)
-\(postData.productData?.cacheKey ?? "")
-\(postData.presentedOfferingIdentifier ?? "")-\(postData.observerMode)
-\(postData.subscriberAttributesByKey?.debugDescription ?? "")"
"""

Your app user ID usage seems correct, so your theory about "so many times" could explain it. If the receipt is very large, we're creating an incredibly long cache key string... I'm going to submit a PR with a suggested solution.

michaelAtRC commented 1 year ago

Hey @swrobel

@NachoSoto fix should solve this, would you like me to keep this ticket open for now?

swrobel commented 1 year ago

would you like me to keep this ticket open for now?

Yes, until it's merged & released and I can test it

kgaidis commented 1 year ago

I'm on 4.12.0 and potentially experiencing a similar issue.

The app randomly starts freezing and then either recovers or crashes.

I also likely have a test user that is constantly subscribing to a in app purchase/subscription.

Posting logs from several crashes if helpful:

Exception Type:  EXC_CRASH (SIGKILL)
Exception Codes: 0x0000000000000000, 0x0000000000000000
Termination Reason: FRONTBOARD 2343432205 
<RBSTerminateContext| domain:10 code:0x8BADF00D explanation:scene-update watchdog transgression: application<com.refocus.refocus>:17524 exhausted real (wall clock) time allowance of 10.00 seconds
ProcessVisibility: Foreground
ProcessState: Running
WatchdogEvent: scene-update
WatchdogVisibility: Background
WatchdogCPUStatistics: (
"Elapsed total CPU time (seconds): 27.530 (user 19.880, system 7.650), 46% CPU",
"Elapsed application CPU time (seconds): 9.827, 16% CPU"
) reportType:CrashLog maxTerminationResistance:Interactive>

Triggered by Thread:  0

Thread 0 name:   Dispatch queue: com.apple.main-thread
Thread 0 Crashed:
0   CoreFoundation                         0x1aa73b948 -[__NSCFString characterAtIndex:] + 0
1   libswiftCore.dylib                     0x1a470f23c String.UTF8View._foreignIndex(after:) + 88
2   libswiftCore.dylib                     0x1a46f61ec specialized __StringStorage.appendInPlace<A>(_:isASCII:) + 504
3   libswiftCore.dylib                     0x1a46f5e04 _StringGuts._foreignAppendInPlace(_:) + 144
4   libswiftCore.dylib                     0x1a4685004 Character.write<A>(to:) + 56
5   libswiftCore.dylib                     0x1a450825c DefaultStringInterpolation.appendInterpolation<A>(_:) + 72
6   Refocus                                0x1052b0078 PostReceiptDataOperation.init(configuration:postData:customerInfoResponseHandler:customerInfoCallbackCache:) + 800
7   Refocus                                0x1052afd48 PostReceiptDataOperation.__allocating_init(configuration:postData:customerInfoResponseHandler:customerInfoCallbackCache:) + 80
8   Refocus                                0x1052766c0 CustomerAPI.post(receiptData:appUserID:isRestore:productData:presentedOfferingIdentifier:observerMode:subscriberAttributes:completion:) + 1128
9   Refocus                                0x105272fa4 Backend.post(receiptData:appUserID:isRestore:productData:presentedOfferingIdentifier:observerMode:subscriberAttributes:completion:) + 312
10  Refocus                                0x10532567c 
Exception Type:  EXC_CRASH (SIGKILL)
Exception Codes: 0x0000000000000000, 0x0000000000000000
Termination Reason: FRONTBOARD 2343432205 
<RBSTerminateContext| domain:10 code:0x8BADF00D explanation:scene-update watchdog transgression: application<com.refocus.refocus>:17674 exhausted real (wall clock) time allowance of 10.00 seconds
ProcessVisibility: Foreground
ProcessState: Running
WatchdogEvent: scene-update
WatchdogVisibility: Foreground
WatchdogCPUStatistics: (
"Elapsed total CPU time (seconds): 17.620 (user 14.150, system 3.470), 29% CPU",
"Elapsed application CPU time (seconds): 9.980, 17% CPU"
) reportType:CrashLog maxTerminationResistance:Interactive>

Triggered by Thread:  0

Thread 0 name:   Dispatch queue: com.apple.main-thread
Thread 0 Crashed:
0   libswiftCore.dylib                     0x1a46f1c0c _stringCompareFastUTF8Abnormal(_:_:expecting:) + 80
1   libswiftCore.dylib                     0x1a45af600 __RawDictionaryStorage.find<A>(_:hashValue:) + 300
2   libswiftCore.dylib                     0x1a45af600 __RawDictionaryStorage.find<A>(_:hashValue:) + 300
3   libswiftCore.dylib                     0x1a45b6594 _NativeDictionary.setValue(_:forKey:isUnique:) + 188
4   libswiftCore.dylib                     0x1a458ec00 Dictionary._Variant.setValue(_:forKey:) + 252
5   libswiftCore.dylib                     0x1a4537254 Dictionary.subscript.setter + 512
6   Refocus                                0x10248bbac closure #1 in CallbackCache.add(callback:) + 832
7   Refocus                                0x10248bc14 partial apply for closure #1 in CallbackCache.add(callback:) + 40
8   Refocus                                0x10246e690 closure #1 in Atomic.modify<A>(_:) + 136
9   Refocus                                0x10246e894 partial apply for closure #1 in Atomic.modify<A>(_:) + 44
10  Refocus                                0x102474fe0 Lock.perform<A>(_:) + 140
11  Refocus                                0x10246e2e4 Atomic.modify<A>(_:) + 160
12  Refocus                                0x10248b828 CallbackCache.add(callback:) + 208
13  Refocus                                0x10248e724 CustomerAPI.post(receiptData:appUserID:isRestore:productData:presentedOfferingIdentifier:observerMode:subscriberAttributes:completion:) + 1228
14  Refocus                                0x10248afa4 Backend.post(receiptData:appUserID:isRestore:productData:presentedOfferingIdentifier:observerMode:subscriberAttributes:completion:) + 312
15  Refocus                                0x10253d67c PurchasesOrchestrator.postReceipt(withTransaction:receiptData:products:storefront:) + 1180
16  Refocus                                0x10253d1c8 closure #1 in PurchasesOrchestrator.fetchProductsAndPostReceipt(withTransaction:receiptData:storefront:) + 208
17  Refocus                                0x102532580 closure #1 in closure #2 in PurchasesOrchestrator.products(withIdentifiers:completion:) + 396
18  Refocus                                0x102478de0 thunk for @escaping @callee_guaranteed () -> () + 48
19  libdispatch.dylib                      0x1b1d174b4 _dispatch_call_block_and_release + 32
20  libdispatch.dylib                      0x1b1d18fdc _dispatch_client_callout + 20
21  libdispatch.dylib                      0x1b1d277f4 _dispatch_main_queue_drain + 928
22  libdispatch.dylib                      0x1b1d27444 _dispatch_main_queue_callback_4CF + 44
23  CoreFoundation                         0x1aa7966d8 __CFRUNLOOP_IS_SERVICING_THE_MAIN_DISPATCH_QUEUE__ + 16
24  CoreFoundation                         0x1aa77803c __CFRunLoopRun + 2036
25  CoreFoundation                         0x1aa77cec0 CFRunLoopRunSpecific
Exception Type:  EXC_CRASH (SIGKILL)
Exception Codes: 0x0000000000000000, 0x0000000000000000
Termination Reason: FRONTBOARD 2343432205 
<RBSTerminateContext| domain:10 code:0x8BADF00D explanation:scene-update watchdog transgression: application<com.refocus.refocus>:18600 exhausted real (wall clock) time allowance of 10.00 seconds
ProcessVisibility: Background
ProcessState: Running
WatchdogEvent: scene-update
WatchdogVisibility: Background
WatchdogCPUStatistics: (
"Elapsed total CPU time (seconds): 28.220 (user 23.840, system 4.380), 46% CPU",
"Elapsed application CPU time (seconds): 10.412, 17% CPU"
) reportType:CrashLog maxTerminationResistance:Interactive>

Triggered by Thread:  0

Thread 0 name:   Dispatch queue: com.apple.main-thread
Thread 0 Crashed:
0   libswiftCore.dylib                     0x1a46e2664 specialized _StringGutsSlice.withFastUTF8<A>(_:) + 208
1   libswiftCore.dylib                     0x1a46e25f0 specialized _StringGutsSlice.withFastUTF8<A>(_:) + 92
2   libswiftCore.dylib                     0x1a46e2c90 specialized _StringGutsSlice._withNFCCodeUnits(_:) + 552
3   libswiftCore.dylib                     0x1a46e1fe8 _StringGutsSlice._normalizedHash(into:) + 120
4   libswiftCore.dylib                     0x1a46e230c protocol witness for Hashable._rawHashValue(seed:) in conformance String + 148
5   libswiftCore.dylib                     0x1a45aec88 __RawDictionaryStorage.find<A>(_:) + 60
6   libswiftCore.dylib                     0x1a45b3c44 Dictionary._Variant.subscript.getter + 220
7   Refocus                                0x100aa39a0 closure #1 in CallbackCache.add(callback:) + 308
8   Refocus                                0x100aa3c14 partial apply for closure #1 in CallbackCache.add(callback:) + 40
9   Refocus                                0x100a86690 closure #1 in Atomic.modify<A>(_:) + 136
10  Refocus                                0x100a86894 partial apply for closure #1 in Atomic.modify<A>(_:) + 44
11  Refocus                                0x100a8cfe0 Lock.perform<A>(_:) + 140
12  Refocus                                0x100a862e4 Atomic.modify<A>(_:) + 160
13  Refocus                                0x100aa3828 CallbackCache.add(callback:) + 208
14  Refocus                                0x100aa6724 CustomerAPI.post(receiptData:appUserID:isRestore:productData:presentedOfferingIdentifier:observerMode:subscriberAttributes:completion:) + 1228
15  Refocus                                0x100aa2fa4 Backend.post(receiptData:appUserID:isRestore:productData:presentedOfferingIdentifier:observerMode:subscriberAttributes:completion:) + 312
16  Refocus                                0x100b5567c PurchasesOrchestrator.postReceipt(withTransaction:receiptData:products:storefront:) + 1180
17  Refocus                                0x100b551c8 closure #1 in PurchasesOrchestrator.fetchProductsAndPostReceipt(withTransaction:receiptData:storefront:) + 208
18  Refocus                                0x100b4a580 closure #1 in closure #2 in PurchasesOrchestrator.products(withIdentifiers:completion:) + 396
19  Refocus                                0x100a90de0 thunk for @escaping @callee_guaranteed () -> () + 48
20  libdispatch.dylib                      0x1b1d174b4 _dispatch_call_bl
NachoSoto commented 1 year ago

Thanks! That looks indeed like the same issue, and I believe #2199 will fix it. If you could try with that branch it would be really helpful if you could confirm that the hang no longer happens 👍🏻

aboedo commented 1 year ago

Update here: the fix is out in 4.17.0! Thanks @swrobel and @kgaidis for reporting!

github-actions[bot] commented 1 year ago

This issue has been automatically locked due to no recent activity after it was closed. Please open a new issue for related reports.