Skip to content

Purchases.shared.purchase completion not called when calling getCustomerInfo from receivedUpdated in PurchasesDelegate #2410

Description

@bengilroy

Describe the bug
A clear and concise description of what the bug is. The more detail you can provide the faster our team will be able to triage and resolve the issue. Do not remove any of the steps from the template below. If a step is not applicable to your issue, please leave that step empty.

When making a purchase, the purchase seems to go through successfully as you see the 'You're all set' alert – but after that the Purchases.shared.purchase completion handler is never called and the app locks up completely.

  1. Environment
    1. Platform: iOS
    2. SDK version: 4.17.10 (also tried 4.17.9 with same result)
    3. StoreKit 2 (disabled with useStoreKit2IfEnabled(false)) (Y/N): Yes (using StoreKit 2 if available)
    4. OS version: iOS 16.4.1
    5. Xcode version: 14.3
    6. How widespread is the issue. Percentage of devices affected. – Not sure, but is happening every time for me during testing.
  2. Debug logs that reproduce the issue

2023-04-15 23:01:15.450730+0100 MyApp[6268:1740291] [Purchases] - DEBUG: ℹ️ Configuring SDK using RevenueCat's UserDefaults suite.
2023-04-15 23:01:15.451467+0100 MyApp[6268:1740291] [Purchases] - DEBUG: 👤 Identifying App User ID
2023-04-15 23:01:15.453103+0100 MyApp[6268:1740291] [Purchases] - DEBUG: ℹ️ Debug logging enabled
2023-04-15 23:01:15.453130+0100 MyApp[6268:1740291] [Purchases] - INFO: ℹ️ StoreKit 2 support enabled
2023-04-15 23:01:15.453156+0100 MyApp[6268:1740291] [Purchases] - DEBUG: ℹ️ SDK Version - 4.17.10
2023-04-15 23:01:15.453172+0100 MyApp[6268:1740291] [Purchases] - DEBUG: ℹ️ Bundle ID - com.my.app
2023-04-15 23:01:15.453373+0100 MyApp[6268:1740291] [Purchases] - DEBUG: ℹ️ System Version - Version 16.4.1 (Build 20E252)
2023-04-15 23:01:15.453396+0100 MyApp[6268:1740291] [Purchases] - DEBUG: ℹ️ Not using a simulator.
2023-04-15 23:01:15.453415+0100 MyApp[6268:1740291] [Purchases] - DEBUG: 👤 No initial App User ID
2023-04-15 23:01:15.453646+0100 MyApp[6268:1740291] [Purchases] - DEBUG: ℹ️ Delegate set
2023-04-15 23:01:17.966111+0100 MyApp[6268:1740323] [Purchases] - DEBUG: ℹ️ GetCustomerInfoOperation: Started
2023-04-15 23:01:17.966270+0100 MyApp[6268:1740323] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request GET subscribers/$RCAnonymousID%3Afb4793737e754fccb7d0e46414ad1ab1
2023-04-15 23:01:18.006080+0100 MyApp[6268:1740291] [Purchases] - DEBUG: ℹ️ applicationDidBecomeActive
2023-04-15 23:01:18.009987+0100 MyApp[6268:1740291] [Purchases] - DEBUG: ℹ️ Offerings cache is stale, updating caches
2023-04-15 23:01:18.010131+0100 MyApp[6268:1740321] [Purchases] - DEBUG: ℹ️ Network operation 'GetOfferingsOperation' found with the same cache key 'GetOfferingsOpe...'. Skipping request.
2023-04-15 23:01:18.010832+0100 MyApp[6268:1740323] [Purchases] - DEBUG: ℹ️ API request started: GET /v1/subscribers/$RCAnonymousID:fb4793737e754fccb7d0e46414ad1ab1
2023-04-15 23:01:19.219106+0100 MyApp[6268:1740318] [Purchases] - DEBUG: ℹ️ API request completed: GET /v1/subscribers/$RCAnonymousID:fb4793737e754fccb7d0e46414ad1ab1 (200)
2023-04-15 23:01:19.240147+0100 MyApp[6268:1740318] [Purchases] - DEBUG: ℹ️ Sending latest CustomerInfo to delegate.
2023-04-15 23:01:19.240257+0100 MyApp[6268:1740318] [Purchases] - DEBUG: 😻 CustomerInfo updated from network.
2023-04-15 23:01:19.240310+0100 MyApp[6268:1740291] [Purchases] - DEBUG: ℹ️ Detected active subscriptions changed. Clearing trial or intro eligibility cache.
2023-04-15 23:01:19.240339+0100 MyApp[6268:1740318] [Purchases] - DEBUG: ℹ️ GetCustomerInfoOperation: Finished
2023-04-15 23:01:20.544260+0100 MyApp[6268:1740318] [Purchases] - DEBUG: ℹ️ Serial request done: GET subscribers/$RCAnonymousID%3Afb4793737e754fccb7d0e46414ad1ab1, 0 requests left in the queue
0325] [Purchases] - DEBUG: ℹ️ GetOfferingsOperation: Started
2023-04-15 23:01:20.544688+0100 MyApp[6268:1740325] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request GET subscribers/$RCAnonymousID%3Afb4793737e754fccb7d0e46414ad1ab1/offerings
2023-04-15 23:01:20.548047+0100 MyApp[6268:1740325] [Purchases] - DEBUG: ℹ️ API request started: GET /v1/subscribers/$RCAnonymousID:fb4793737e754fccb7d0e46414ad1ab1/offerings
2023-04-15 23:01:20.714820+0100 MyApp[6268:1740321] [Purchases] - DEBUG: ℹ️ API request completed: GET /v1/subscribers/$RCAnonymousID:fb4793737e754fccb7d0e46414ad1ab1/offerings (200)
2023-04-15 23:01:20.725824+0100 MyApp[6268:1740321] [Purchases] - DEBUG: ℹ️ No existing products cached, starting store products request for: ["code_0999_1y_3d0", "code_0199_1m", "code_1499_lifetime"]
2023-04-15 23:01:20.726056+0100 MyApp[6268:1740321] [Purchases] - DEBUG: ℹ️ Found an existing request for products: ["code_0199_1m", "code_0999_1y_3d0", "code_1499_lifetime"], appending to completion
2023-04-15 23:01:20.726199+0100 MyApp[6268:1740321] [Purchases] - DEBUG: ℹ️ GetOfferingsOperation: Finished
2023-04-15 23:01:20.726364+0100 MyApp[6268:1740321] [Purchases] - DEBUG: ℹ️ Serial request done: GET subscribers/$RCAnonymousID%3Afb4793737e754fccb7d0e46414ad1ab1/offerings, 0 requests left in the queue
2023-04-15 23:01:20.791674+0100 MyApp[6268:1740321] [Purchases] - DEBUG: 😻 Store products request received response
2023-04-15 23:01:20.791852+0100 MyApp[6268:1740321] [Purchases] - DEBUG: ℹ️ Store products request finished
2023-04-15 23:01:24.088874+0100 MyApp[6268:1740291] [Purchases] - DEBUG: ℹ️ Vending CustomerInfo from cache.
2023-04-15 23:01:24.089814+0100 MyApp[6268:1740291] [Purchases] - DEBUG: ℹ️ Vending CustomerInfo from cache.
2023-04-15 23:01:25.505229+0100 MyApp[6268:1740291] [Purchases] - DEBUG: ℹ️ Vending Offerings from cache
2023-04-15 23:01:28.357893+0100 MyApp[6268:1740291] [Purchases] - INFO: 💰 Purchasing Product 'code_0199_1m' from package in Offering 'code_default'
2023-04-15 23:01:46.003011+0100 MyApp[6268:1740291] [Purchases] - DEBUG: ℹ️ applicationDidBecomeActive
2023-04-15 23:02:00.494634+0100 MyApp[6268:1740658] [Purchases] - WARN: 🍎⚠️ StoreKit 2 purchase took longer than expected (32.13 seconds)
2023-04-15 23:02:00.510391+0100 MyApp[6268:1740899] [Purchases] - DEBUG: ℹ️ Force refreshing the receipt to get latest transactions from Apple.
2023-04-15 23:02:00.510491+0100 MyApp[6268:1740899] [Purchases] - DEBUG: ℹ️ SKReceiptRefreshRequest started
2023-04-15 23:02:00.555245+0100 MyApp[6268:1740291] [Purchases] - DEBUG: ℹ️ applicationDidBecomeActive
2023-04-15 23:02:01.062538+0100 MyApp[6268:1740291] [Purchases] - DEBUG: ℹ️ SKReceiptRefreshRequest finished
2023-04-15 23:02:01.063190+0100 MyApp[6268:1740291] [Purchases] - DEBUG: ℹ️ Loaded receipt from url file:///private/var/mobile/Containers/Data/Application/6F375688-166D-46EC-A415-9FAC4D5EF186/StoreKit/sandboxReceipt
2023-04-15 23:02:01.063368+0100 MyApp[6268:1740291] [Purchases] - DEBUG: ℹ️ Skipping products request for these products because they were already cached: ["code_0199_1m"]
2023-04-15 23:02:01.064343+0100 MyApp[6268:1740291] [Purchases] - DEBUG: ℹ️ Found 0 unsynced attributes for App User ID: $RCAnonymousID:fb4793737e754fccb7d0e46414ad1ab1
2023-04-15 23:02:01.071097+0100 MyApp[6268:1740899] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Started
2023-04-15 23:02:01.071270+0100 MyApp[6268:1740899] [Purchases] - INFO: ℹ️ Parsing receipt
2023-04-15 23:02:01.081177+0100 MyApp[6268:1740899] [Purchases] - INFO: ℹ️ Receipt parsed successfully
2023-04-15 23:02:01.083535+0100 MyApp[6268:1740899] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Posting receipt (note: the contents might not be up-to-date, but it will be refreshed with Apple's servers):
2023-04-15 23:02:01.083911+0100 MyApp[6268:1740899] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request POST receipts
2023-04-15 23:02:01.087290+0100 MyApp[6268:1740899] [Purchases] - DEBUG: ℹ️ API request started: POST /v1/receipts
2023-04-15 23:02:02.443717+0100 MyApp[6268:1740899] [Purchases] - DEBUG: ℹ️ API request completed: POST /v1/receipts (200)
2023-04-15 23:02:02.449077+0100 MyApp[6268:1740899] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Finished
2023-04-15 23:02:02.449342+0100 MyApp[6268:1740899] [Purchases] - DEBUG: ℹ️ Serial request done: POST receipts, 0 requests left in the queue
2023-04-15 23:02:02.452329+0100 MyApp[6268:1740291] [Purchases] - DEBUG: ℹ️ Sending updated CustomerInfo to delegate.
2023-04-15 23:02:02.452437+0100 MyApp[6268:1740291] [Purchases] - DEBUG: ℹ️ Detected active subscriptions changed. Clearing trial or intro eligibility cache.
  1. Steps to reproduce, with a description of expected vs. actual behavior
  • On physical device, launch app in debug mode, offerings fetched successfully
  • Start purchase of product
  • Enter sandbox tester password
  • Purchase successful (i.e. you see the normal 'You're all set' alert)
  • Completion handler never called even after several minutes
  • App's loading spinner is still spinning, but UI is completely unresponsive suggesting some sort of lock up.
  1. Other information (e.g. stacktraces, related issues, suggestions how to fix, links for us to have context, eg. stackoverflow, etc.)

Additional context
I have tried this several times now and each time the SDK gets stuck as the 'Detected active subscriptions changed. Clearing trial or intro eligibility cache.' log so I'm wondering if it's clearing the cache causing a lock up. This is my first week using RevenueCat so I'm not sure if there are any workarounds at the moment. I'm also not sure yet if this is happening in sandbox only, or in production too.

Metadata

Metadata

Assignees

Type

No type
No fields configured for issues without a type.

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions