Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Purchases.shared.purchase(product: product) completion is not called #2415

Closed
5 tasks done
DavidKadlcek opened this issue Apr 19, 2023 · 37 comments
Closed
5 tasks done
Labels

Comments

@DavidKadlcek
Copy link

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.

The problem is that Purchases.shared.purchase(product: product) { // This is not called } completion is not called when I purchase the product. In the console it is showing [Purchases] - INFO: 💰 Finishing transaction '2000000313661251' for product 'david.kadlcek.GuessWho.annualAccess' (debug log). I try it on the physical device from Xcode and Testflight, and also on the simulator with ConfigurationStoreKit. (Same problem). UI is not frozen. I think that the subscription on the latest version of the app store is working.

  1. Environment
    1. Platform: iOS
    2. SDK version: 4.17.10
    3. StoreKit 2 (disabled with useStoreKit2IfEnabled(false)) (Y/N): N (Not using StoreKit2)
    4. OS version: 16.3.1
    5. Xcode version: 14.3
    6. How widespread is the issue. Percentage of devices affected. - I don't know. I think that my latest version (2 weeks ago) is working on the AppStore, but current version on simulator / physical device from Xcode/Testflight is not working.
  2. Debug logs that reproduce the issue

2023-04-15 10:49:29.216585+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ Configuring SDK using RevenueCat's UserDefaults suite.
2023-04-15 10:49:29.218776+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: 👤 Identifying App User ID
2023-04-15 10:49:29.402004+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ Debug logging enabled
2023-04-15 10:49:29.402080+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ SDK Version - 4.17.10
2023-04-15 10:49:29.402110+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ Bundle ID - david.kadlcek.GuessWho
2023-04-15 10:49:29.403969+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ System Version - Version 16.3.1 (Build 20D67)
2023-04-15 10:49:29.404011+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ Not using a simulator.
2023-04-15 10:49:29.404035+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: 👤 No initial App User ID
2023-04-15 10:49:29.468838+0200 GuessWho[11394:2627541] [Purchases] - DEBUG: ℹ️ PostAdServicesTokenOperation: Started
2023-04-15 10:49:29.469139+0200 GuessWho[11394:2627541] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request POST subscribers/$RCAnonymousID%3A480b49d4543f45148f3b7b111243e5fd/adservices_attribution
2023-04-15 10:49:29.479099+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ setting reserved attribute: $firebaseAppInstanceId
2023-04-15 10:49:29.481395+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ Attribute set locally: [SubscriberAttribute] key: $firebaseAppInstanceId value: 3C23DD90C49F4D2CB50E8692C3C66DF9 setTime: 2023-04-15 08:49:29 +0000. It will be synced to the backend when the app backgrounds/foregrounds or when a purchase is made.
2023-04-15 10:49:29.481806+0200 GuessWho[11394:2627541] [Purchases] - DEBUG: ℹ️ API request started: POST /v1/subscribers/$RCAnonymousID:480b49d4543f45148f3b7b111243e5fd/adservices_attribution
2023-04-15 10:49:29.485342+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ No cached Offerings, fetching from network
2023-04-15 10:49:29.711723+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ CustomerInfo cache is stale, updating from network in foreground.
2023-04-15 10:49:29.714061+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ applicationDidBecomeActive
2023-04-15 10:49:29.714292+0200 GuessWho[11394:2627569] [Purchases] - DEBUG: ℹ️ Network operation 'GetCustomerInfoOperation' found with the same cache key 'GetCustomerInfo...'. Skipping request.
2023-04-15 10:49:29.714642+0200 GuessWho[11394:2627569] [Purchases] - DEBUG: ℹ️ Network operation 'GetOfferingsOperation' found with the same cache key 'GetOfferingsOpe...'. Skipping request.
2023-04-15 10:49:29.715719+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ CustomerInfo cache is stale, updating from network in foreground.
2023-04-15 10:49:29.715918+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ Offerings cache is stale, updating caches
2023-04-15 10:49:29.715960+0200 GuessWho[11394:2627539] [Purchases] - DEBUG: ℹ️ Network operation 'GetCustomerInfoOperation' found with the same cache key 'GetCustomerInfo...'. Skipping request.
2023-04-15 10:49:29.716515+0200 GuessWho[11394:2627539] [Purchases] - DEBUG: ℹ️ Network operation 'GetOfferingsOperation' found with the same cache key 'GetOfferingsOpe...'. Skipping request.
2023-04-15 10:49:30.247941+0200 GuessWho[11394:2627572] [Purchases] - DEBUG: ℹ️ API request completed: POST /v1/subscribers/$RCAnonymousID:480b49d4543f45148f3b7b111243e5fd/adservices_attribution (200)
2023-04-15 10:49:30.248233+0200 GuessWho[11394:2627572] [Purchases] - DEBUG: ℹ️ AdServices attribution token successfully posted
2023-04-15 10:49:30.248291+0200 GuessWho[11394:2627572] [Purchases] - DEBUG: ℹ️ PostAdServicesTokenOperation: Finished
2023-04-15 10:49:30.248520+0200 GuessWho[11394:2627569] [Purchases] - DEBUG: ℹ️ GetOfferingsOperation: Started
2023-04-15 10:49:30.248585+0200 GuessWho[11394:2627572] [Purchases] - DEBUG: ℹ️ Serial request done: POST subscribers/$RCAnonymousID%3A480b49d4543f45148f3b7b111243e5fd/adservices_attribution, 0 requests left in the queue
2023-04-15 10:49:30.248737+0200 GuessWho[11394:2627569] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request GET subscribers/$RCAnonymousID%3A480b49d4543f45148f3b7b111243e5fd/offerings
2023-04-15 10:49:30.250120+0200 GuessWho[11394:2627569] [Purchases] - DEBUG: ℹ️ API request started: GET /v1/subscribers/$RCAnonymousID:480b49d4543f45148f3b7b111243e5fd/offerings
2023-04-15 10:49:30.364101+0200 GuessWho[11394:2627572] [Purchases] - DEBUG: ℹ️ API request completed: GET /v1/subscribers/$RCAnonymousID:480b49d4543f45148f3b7b111243e5fd/offerings (200)
2023-04-15 10:49:30.370290+0200 GuessWho[11394:2627572] [Purchases] - DEBUG: ℹ️ No existing products cached, starting store products request for: ["david.kadlcek.GuessWho.annualAccess", "david.kadlcek.GuessWho.monthlyAccess", "david.kadlcek.GuessWho.weeklyAccess", "david.kadlcek.GuessWho.annualAccessLimited"]
2023-04-15 10:49:30.370414+0200 GuessWho[11394:2627572] [Purchases] - DEBUG: ℹ️ Found an existing request for products: ["david.kadlcek.GuessWho.annualAccess", "david.kadlcek.GuessWho.annualAccessLimited", "david.kadlcek.GuessWho.weeklyAccess", "david.kadlcek.GuessWho.monthlyAccess"], appending to completion
2023-04-15 10:49:30.370415+0200 GuessWho[11394:2627543] [Purchases] - DEBUG: ℹ️ No existing products cached, starting store products request for: ["david.kadlcek.GuessWho.annualAccess", "david.kadlcek.GuessWho.monthlyAccess", "david.kadlcek.GuessWho.weeklyAccess", "david.kadlcek.GuessWho.annualAccessLimited"]
2023-04-15 10:49:30.370478+0200 GuessWho[11394:2627572] [Purchases] - DEBUG: ℹ️ Found an existing request for products: ["david.kadlcek.GuessWho.annualAccessLimited", "david.kadlcek.GuessWho.annualAccess", "david.kadlcek.GuessWho.monthlyAccess", "david.kadlcek.GuessWho.weeklyAccess"], appending to completion
2023-04-15 10:49:30.370512+0200 GuessWho[11394:2627572] [Purchases] - DEBUG: ℹ️ GetOfferingsOperation: Finished
2023-04-15 10:49:30.370586+0200 GuessWho[11394:2627572] [Purchases] - DEBUG: ℹ️ Serial request done: GET subscribers/$RCAnonymousID%3A480b49d4543f45148f3b7b111243e5fd/offerings, 0 requests left in the queue
2023-04-15 10:49:30.370707+0200 GuessWho[11394:2627572] [Purchases] - DEBUG: ℹ️ GetCustomerInfoOperation: Started
2023-04-15 10:49:30.370967+0200 GuessWho[11394:2627572] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request GET subscribers/$RCAnonymousID%3A480b49d4543f45148f3b7b111243e5fd
2023-04-15 10:49:30.371908+0200 GuessWho[11394:2627572] [Purchases] - DEBUG: ℹ️ API request started: GET /v1/subscribers/$RCAnonymousID:480b49d4543f45148f3b7b111243e5fd
2023-04-15 10:49:30.418080+0200 GuessWho[11394:2627543] [Purchases] - DEBUG: 😻 Store products request finished
2023-04-15 10:49:30.418091+0200 GuessWho[11394:2627572] [Purchases] - DEBUG: 😻 Store products request received response
2023-04-15 10:49:30.419446+0200 GuessWho[11394:2627572] [Purchases] - DEBUG: ℹ️ Package 'david.kadlcek.GuessWho.annualAccessLimited' in offering 'Limited' has a custom duration.
2023-04-15 10:49:30.419583+0200 GuessWho[11394:2627572] [Purchases] - DEBUG: ℹ️ Package 'david.kadlcek.GuessWho.annualAccessLimited' in offering 'Limited' has a custom duration.
2023-04-15 10:49:30.419648+0200 GuessWho[11394:2627572] [Purchases] - DEBUG: ℹ️ Package 'david.kadlcek.GuessWho.annualAccessLimited' in offering 'Limited' has a custom duration.
2023-04-15 10:49:30.429989+0200 GuessWho[11394:2627273] [Purchases] - WARN: 🍎‼️ Unable to load receipt, ensure you are logged in to a valid Apple account.
2023-04-15 10:49:30.430078+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ Skipping products request for these products because they were already cached: ["david.kadlcek.GuessWho.annualAccess", "david.kadlcek.GuessWho.annualAccessLimited", "david.kadlcek.GuessWho.weeklyAccess", "david.kadlcek.GuessWho.monthlyAccess"]
2023-04-15 10:49:30.518601+0200 GuessWho[11394:2627543] [Purchases] - DEBUG: ℹ️ API request completed: GET /v1/subscribers/$RCAnonymousID:480b49d4543f45148f3b7b111243e5fd (200)
2023-04-15 10:49:30.528390+0200 GuessWho[11394:2627543] [Purchases] - DEBUG: ℹ️ Sending latest CustomerInfo to delegate.
2023-04-15 10:49:30.528473+0200 GuessWho[11394:2627543] [Purchases] - DEBUG: 😻 CustomerInfo updated from network.
2023-04-15 10:49:30.528497+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ Detected active subscriptions changed. Clearing trial or intro eligibility cache.
2023-04-15 10:49:30.529130+0200 GuessWho[11394:2627543] [Purchases] - DEBUG: 😻 CustomerInfo updated from network.
2023-04-15 10:49:30.529605+0200 GuessWho[11394:2627543] [Purchases] - DEBUG: 😻 CustomerInfo updated from network.
2023-04-15 10:49:30.529656+0200 GuessWho[11394:2627543] [Purchases] - DEBUG: ℹ️ GetCustomerInfoOperation: Finished
2023-04-15 10:49:30.529754+0200 GuessWho[11394:2627543] [Purchases] - DEBUG: ℹ️ Serial request done: GET subscribers/$RCAnonymousID%3A480b49d4543f45148f3b7b111243e5fd, 0 requests left in the queue
2023-04-15 10:49:30.529761+0200 GuessWho[11394:2627572] [Purchases] - DEBUG: ℹ️ PostSubscriberAttributesOperation: Started
2023-04-15 10:49:30.529880+0200 GuessWho[11394:2627572] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request POST subscribers/$RCAnonymousID%3A480b49d4543f45148f3b7b111243e5fd/attributes
2023-04-15 10:49:30.533749+0200 GuessWho[11394:2627572] [Purchases] - DEBUG: ℹ️ API request started: POST /v1/subscribers/$RCAnonymousID:480b49d4543f45148f3b7b111243e5fd/attributes
2023-04-15 10:49:30.810505+0200 GuessWho[11394:2627541] [Purchases] - DEBUG: ℹ️ API request completed: POST /v1/subscribers/$RCAnonymousID:480b49d4543f45148f3b7b111243e5fd/attributes (200)
2023-04-15 10:49:30.811137+0200 GuessWho[11394:2627541] [Purchases] - INFO: ℹ️ Marking attributes as synced for App User ID: $RCAnonymousID:480b49d4543f45148f3b7b111243e5fd:
2023-04-15 10:49:30.811247+0200 GuessWho[11394:2627541] [Purchases] - DEBUG: ℹ️ Found 1 unsynced attributes for App User ID: $RCAnonymousID:480b49d4543f45148f3b7b111243e5fd
2023-04-15 10:49:30.811349+0200 GuessWho[11394:2627541] [Purchases] - DEBUG: ℹ️ Unsynced attributes: ["$firebaseAppInstanceId": [SubscriberAttribute] key: $firebaseAppInstanceId value: 3C23DD90C49F4D2CB50E8692C3C66DF9 setTime: 2023-04-15 08:49:29 +0000]
2627541] [Purchases] - DEBUG: 😻 Subscriber attributes synced successfully for App User ID: $RCAnonymousID:480b49d4543f45148f3b7b111243e5fd
2023-04-15 10:49:30.811768+0200 GuessWho[11394:2627541] [Purchases] - DEBUG: ℹ️ PostSubscriberAttributesOperation: Finished
2023-04-15 10:49:30.811912+0200 GuessWho[11394:2627541] [Purchases] - DEBUG: ℹ️ Serial request done: POST subscribers/$RCAnonymousID%3A480b49d4543f45148f3b7b111243e5fd/attributes, 0 requests left in the queue
2023-04-15 10:49:30.812072+0200 GuessWho[11394:2627544] [Purchases] - DEBUG: ℹ️ GetIntroEligibilityOperation: Started
2023-04-15 10:49:30.812181+0200 GuessWho[11394:2627544] [Purchases] - WARN: 🍎‼️ App running on sandbox without a receipt file. Unable to determine into eligibility unless you've purchased before and there is a receipt available.
2023-04-15 10:49:30.812252+0200 GuessWho[11394:2627544] [Purchases] - DEBUG: ℹ️ GetIntroEligibilityOperation: Finished
] [Purchases] - DEBUG: ℹ️ Caching trial or intro eligibility for products: ["david.kadlcek.GuessWho.weeklyAccess", "david.kadlcek.GuessWho.monthlyAccess"]
2023-04-15 10:49:30.812428+0200 GuessWho[11394:2627541] [Purchases] - DEBUG: ℹ️ PostSubscriberAttributesOperation: Started
2023-04-15 10:49:30.812505+0200 GuessWho[11394:2627541] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request POST subscribers/$RCAnonymousID%3A480b49d4543f45148f3b7b111243e5fd/attributes
2023-04-15 10:49:30.813661+0200 GuessWho[11394:2627541] [Purchases] - DEBUG: ℹ️ API request started: POST /v1/subscribers/$RCAnonymousID:480b49d4543f45148f3b7b111243e5fd/attributes
2023-04-15 10:49:31.084091+0200 GuessWho[11394:2627539] [Purchases] - DEBUG: ℹ️ API request completed: POST /v1/subscribers/$RCAnonymousID:480b49d4543f45148f3b7b111243e5fd/attributes (200)
2023-04-15 10:49:31.084362+0200 GuessWho[11394:2627539] [Purchases] - INFO: ℹ️ Marking attributes as synced for App User ID: $RCAnonymousID:480b49d4543f45148f3b7b111243e5fd:
2023-04-15 10:49:31.084805+0200 GuessWho[11394:2627539] [Purchases] - DEBUG: ℹ️ Found 0 unsynced attributes for App User ID: $RCAnonymousID:480b49d4543f45148f3b7b111243e5fd
2023-04-15 10:49:31.084982+0200 GuessWho[11394:2627539] [Purchases] - DEBUG: 😻 Subscriber attributes synced successfully for App User ID: $RCAnonymousID:480b49d4543f45148f3b7b111243e5fd
2023-04-15 10:49:31.085135+0200 GuessWho[11394:2627539] [Purchases] - DEBUG: ℹ️ PostSubscriberAttributesOperation: Finished
2023-04-15 10:49:31.085467+0200 GuessWho[11394:2627539] [Purchases] - DEBUG: ℹ️ Serial request done: POST subscribers/$RCAnonymousID%3A480b49d4543f45148f3b7b111243e5fd/attributes, 0 requests left in the queue
2023-04-15 10:49:32.252154+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ applicationDidBecomeActive
2023-04-15 10:49:36.657493+0200 GuessWho[11394:2627273] [Purchases] - INFO: 💰 Purchasing Product 'david.kadlcek.GuessWho.annualAccess'
2023-04-15 10:49:36.666244+0200 GuessWho[11394:2627570] [Purchases] - DEBUG: ℹ️ StoreKit1Wrapper (0x0000000281cd8060) updatedTransaction: david.kadlcek.GuessWho.annualAccess 0
2023-04-15 10:50:03.873546+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ applicationDidBecomeActive
2023-04-15 10:50:17.900322+0200 GuessWho[11394:2627963] [Purchases] - DEBUG: ℹ️ StoreKit1Wrapper (0x0000000281cd8060) updatedTransaction: david.kadlcek.GuessWho.annualAccess 2000000313661188 1
2023-04-15 10:50:17.914122+0200 GuessWho[11394:2627963] [Purchases] - DEBUG: ℹ️ Force refreshing the receipt to get latest transactions from Apple.
2023-04-15 10:50:17.914254+0200 GuessWho[11394:2627963] [Purchases] - DEBUG: ℹ️ SKReceiptRefreshRequest started
2023-04-15 10:50:17.944654+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ applicationDidBecomeActive
2023-04-15 10:50:18.836321+0200 GuessWho[11394:2627572] [Purchases] - DEBUG: ℹ️ StoreKit1Wrapper (0x0000000281cd8060) removedTransaction: david.kadlcek.GuessWho.annualAccess 2000000313661188 1
2023-04-15 10:50:18.879267+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ SKReceiptRefreshRequest finished
2023-04-15 10:50:18.879829+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ Loaded receipt from url file:///private/var/mobile/Containers/Data/Application/B41177A3-9F63-4C5D-B8AF-1F0FA9C64437/StoreKit/sandboxReceipt
2023-04-15 10:50:18.879988+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ Skipping products request for these products because they were already cached: ["david.kadlcek.GuessWho.annualAccess"]
2023-04-15 10:50:18.881037+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ Found 0 unsynced attributes for App User ID: $RCAnonymousID:480b49d4543f45148f3b7b111243e5fd
2023-04-15 10:50:18.891614+0200 GuessWho[11394:2627572] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Started
2023-04-15 10:50:18.891840+0200 GuessWho[11394:2627572] [Purchases] - INFO: ℹ️ Parsing receipt
2023-04-15 10:50:18.895865+0200 GuessWho[11394:2627572] [Purchases] - INFO: ℹ️ Receipt parsed successfully
2023-04-15 10:50:18.897704+0200 GuessWho[11394:2627572] [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 10:50:18.897887+0200 GuessWho[11394:2627572] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request POST receipts
2023-04-15 10:50:18.901105+0200 GuessWho[11394:2627572] [Purchases] - DEBUG: ℹ️ API request started: POST /v1/receipts
2023-04-15 10:50:20.101315+0200 GuessWho[11394:2628170] [Purchases] - DEBUG: ℹ️ API request completed: POST /v1/receipts (200)
2023-04-15 10:50:20.115049+0200 GuessWho[11394:2628170] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Finished
2023-04-15 10:50:20.115380+0200 GuessWho[11394:2628170] [Purchases] - DEBUG: ℹ️ Serial request done: POST receipts, 0 requests left in the queue
2023-04-15 10:50:20.124383+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ Sending updated CustomerInfo to delegate.
2023-04-15 10:50:20.124532+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ Detected active subscriptions changed. Clearing trial or intro eligibility cache.
2023-04-15 10:50:20.124634+0200 GuessWho[11394:2627273] [Purchases] - INFO: 💰 Finishing transaction '2000000313661188' for product 'david.kadlcek.GuessWho.annualAccess'
2023-04-15 10:51:23.400894+0200 GuessWho[11394:2628222] [Purchases] - DEBUG: ℹ️ StoreKit1Wrapper (0x0000000281cd8060) updatedTransaction: david.kadlcek.GuessWho.annualAccess 2000000313661251 2000000313661188 1
2023-04-15 10:51:23.415146+0200 GuessWho[11394:2628222] [Purchases] - DEBUG: ℹ️ Force refreshing the receipt to get latest transactions from Apple.
2023-04-15 10:51:23.415275+0200 GuessWho[11394:2628222] [Purchases] - DEBUG: ℹ️ SKReceiptRefreshRequest started
2023-04-15 10:51:23.422926+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ SKReceiptRefreshRequest finished
2023-04-15 10:51:23.423360+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ Loaded receipt from url file:///private/var/mobile/Containers/Data/Application/B41177A3-9F63-4C5D-B8AF-1F0FA9C64437/StoreKit/sandboxReceipt
2023-04-15 10:51:23.423459+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ Skipping products request for these products because they were already cached: ["david.kadlcek.GuessWho.annualAccess"]
2023-04-15 10:51:23.423769+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ Found 0 unsynced attributes for App User ID: $RCAnonymousID:480b49d4543f45148f3b7b111243e5fd
2023-04-15 10:51:23.424196+0200 GuessWho[11394:2628739] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Started
2023-04-15 10:51:23.424309+0200 GuessWho[11394:2628739] [Purchases] - INFO: ℹ️ Parsing receipt
2023-04-15 10:51:23.427448+0200 GuessWho[11394:2628739] [Purchases] - INFO: ℹ️ Receipt parsed successfully
2023-04-15 10:51:23.427875+0200 GuessWho[11394:2628739] [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 10:51:23.428186+0200 GuessWho[11394:2628739] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request POST receipts
2023-04-15 10:51:23.429408+0200 GuessWho[11394:2628739] [Purchases] - DEBUG: ℹ️ API request started: POST /v1/receipts
2023-04-15 10:51:24.009370+0200 GuessWho[11394:2628738] [Purchases] - DEBUG: ℹ️ StoreKit1Wrapper (0x0000000281cd8060) removedTransaction: david.kadlcek.GuessWho.annualAccess 2000000313661251 2000000313661188 1
2023-04-15 10:51:24.491746+0200 GuessWho[11394:2628738] [Purchases] - DEBUG: ℹ️ API request completed: POST /v1/receipts (200)
2023-04-15 10:51:24.496787+0200 GuessWho[11394:2628738] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Finished
2023-04-15 10:51:24.497148+0200 GuessWho[11394:2628738] [Purchases] - DEBUG: ℹ️ Serial request done: POST receipts, 0 requests left in the queue
2023-04-15 10:51:24.501050+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ Sending updated CustomerInfo to delegate.
2023-04-15 10:51:24.501237+0200 GuessWho[11394:2627273] [Purchases] - DEBUG: ℹ️ Detected active subscriptions changed. Clearing trial or intro eligibility cache.
2023-04-15 10:51:24.501374+0200 GuessWho[11394:2627273] [Purchases] - INFO: 💰 Finishing transaction '2000000313661251' for product 'david.kadlcek.GuessWho.annualAccess'

  1. Steps to reproduce, with a description of expected vs. actual behavior
  • On physical/simulator just clicked to subscribe. Apple bottom sheet appears. Then clicked on purchase button. Alert appeared that purchased was successful but there is still loading activity indicator because Purchases.shared.purchase completion handler is not called
  1. Other information (e.g. stacktraces, related issues, suggestions how to fix, links for us to have context, eg. stackoverflow, etc.)

Additional context
No additional context

@RCGitBot
Copy link
Contributor

RCGitBot commented Apr 19, 2023

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

@NachoSoto
Copy link
Contributor

Thanks! Could you share a bit more code, how you're configuring the SDK and the code around the purchase call?

@DavidKadlcek
Copy link
Author

SDK:

private init() {
        Purchases.configure(withAPIKey: RevenueCat.apiKey)
        if #available(iOS 14.3, *) {
            Purchases.shared.attribution.enableAdServicesAttributionTokenCollection()
        }
        
        if let instanceId = Analytics.appInstanceID() {
            Purchases.shared.attribution.setFirebaseAppInstanceID(instanceId)
        }
    }

Making purchase:

func unlockSubscription(type: Subscription, successfulPurchase: @escaping(_ status: StatePurchase) -> Void) {
        guard let product = product(for: type) else {
            return successfulPurchase(.failed)
        }
        
        Purchases.shared.purchase(product: product) { [weak self] (transaction, purchaseInfo, error, userCancelled) in
            if let _ = error, !userCancelled {
                successfulPurchase(.failed)
            } else if userCancelled {
                successfulPurchase(.userCanceled)
            } else {
                self?.hasSubscription = true
                self?.hasTrial = purchaseInfo?.entitlements[RevenueCat.allAccess]?.periodType == .trial && purchaseInfo?.entitlements[RevenueCat.allAccess]?.expirationDate != nil
                successfulPurchase(.purchased)
            }
        }
    }

@NachoSoto
Copy link
Contributor

weak self is unnecessary: the closure is short lived and there can't be a reference cycle. Is your instance being deallocated by any chance?

@NachoSoto
Copy link
Contributor

Also it would be helpful if you can let us know if you're able to reproduce this with StoreKit 2 enabled so we can eliminate one variable and isolate where the bug might be.

@DavidKadlcek
Copy link
Author

I removed weak self and it is still not working. Hm... I need to support an earlier version than iOS 15, that's why I cannot use StoreKit 2

@DavidKadlcek
Copy link
Author

I tried to use StoreKit2 and it works... the success is called

@DavidKadlcek
Copy link
Author

DavidKadlcek commented Apr 19, 2023

Also when I setup Purchases like this:

Purchases.configure(
            with: Configuration.Builder(withAPIKey: RevenueCat.apiKey).with(usesStoreKit2IfAvailable: true).build()
        )

Completion block is called... I leave the Purchases.shared.purchase(product: product) same as above (closures). I just make changes in configuration and it is working. Now I can do purchases. Is it safe? @NachoSoto

@NachoSoto
Copy link
Contributor

Just wanted to isolate this is SK1 only, that's already helpful.

Can you configure the SDK with log level verbose?

Purchases.logLevel = .verbose

That might have extra information to help us figure out the problem. Thanks a lot!

@DavidKadlcek
Copy link
Author

2023-04-19 20:22:20.811651+0200 GuessWho[22415:4879262] [Purchases] - DEBUG: ℹ️ Configuring SDK using RevenueCat's UserDefaults suite.
2023-04-19 20:22:20.813138+0200 GuessWho[22415:4879262] [Purchases] - VERBOSE: DeviceCache.init: DeviceCache (0x0000000281c75740)
2023-04-19 20:22:20.814080+0200 GuessWho[22415:4879262] [Purchases] - DEBUG: 👤 Identifying App User ID
2023-04-19 20:22:20.899275+0200 GuessWho[22415:4879262] [Purchases] - DEBUG: ℹ️ Debug logging enabled
2023-04-19 20:22:20.899403+0200 GuessWho[22415:4879262] [Purchases] - INFO: ℹ️ StoreKit 2 support enabled
2023-04-19 20:22:20.899440+0200 GuessWho[22415:4879262] [Purchases] - DEBUG: ℹ️ SDK Version - 4.17.10
2023-04-19 20:22:20.899478+0200 GuessWho[22415:4879262] [Purchases] - DEBUG: ℹ️ Bundle ID - david.kadlcek.GuessWho
2023-04-19 20:22:20.900406+0200 GuessWho[22415:4879262] [Purchases] - DEBUG: ℹ️ System Version - Version 16.3.1 (Build 20D67)
2023-04-19 20:22:20.900449+0200 GuessWho[22415:4879262] [Purchases] - DEBUG: ℹ️ Not using a simulator.
2023-04-19 20:22:20.900478+0200 GuessWho[22415:4879262] [Purchases] - DEBUG: 👤 No initial App User ID
2023-04-19 20:22:20.901684+0200 GuessWho[22415:4879262] [Purchases] - VERBOSE: Purchases.init: created new Purchases instance: Purchases (0x0000000280178380)
2023-04-19 20:22:20.930752+0200 GuessWho[22415:4879499] [Purchases] - DEBUG: ℹ️ PostAdServicesTokenOperation: Started
2023-04-19 20:22:20.931014+0200 GuessWho[22415:4879499] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request POST subscribers/$RCAnonymousID%3A7a9ea231e4e5468f80a05b65977361ce/adservices_attribution
2023-04-19 20:22:20.940832+0200 GuessWho[22415:4879262] [Purchases] - DEBUG: ℹ️ setting reserved attribute: $firebaseAppInstanceId
2023-04-19 20:22:20.941747+0200 GuessWho[22415:4879262] [Purchases] - DEBUG: ℹ️ Attribute set locally: [SubscriberAttribute] key: $firebaseAppInstanceId value: 241CCECA552F467F9319747AF89D77E3 setTime: 2023-04-19 18:22:20 +0000. It will be synced to the backend when the app backgrounds/foregrounds or when a purchase is made.
2023-04-19 20:22:20.942728+0200 GuessWho[22415:4879499] [Purchases] - DEBUG: ℹ️ API request started: POST /v1/subscribers/$RCAnonymousID:7a9ea231e4e5468f80a05b65977361ce/adservices_attribution
2023-04-19 20:22:20.945139+0200 GuessWho[22415:4879262] [Purchases] - DEBUG: ℹ️ No cached Offerings, fetching from network
2023-04-19 20:22:21.203945+0200 GuessWho[22415:4879262] [Purchases] - DEBUG: ℹ️ CustomerInfo cache is stale, updating from network in foreground.
2023-04-19 20:22:21.205445+0200 GuessWho[22415:4879499] [Purchases] - DEBUG: ℹ️ Network operation 'GetCustomerInfoOperation' found with the same cache key 'GetCustomerInfo...'. Skipping request.
2023-04-19 20:22:21.205485+0200 GuessWho[22415:4879499] [Purchases] - DEBUG: ℹ️ Network operation 'GetOfferingsOperation' found with the same cache key 'GetOfferingsOpe...'. Skipping request.
2023-04-19 20:22:21.206259+0200 GuessWho[22415:4879262] [Purchases] - DEBUG: ℹ️ applicationDidBecomeActive
2023-04-19 20:22:21.207710+0200 GuessWho[22415:4879262] [Purchases] - DEBUG: ℹ️ CustomerInfo cache is stale, updating from network in foreground.
2023-04-19 20:22:21.207878+0200 GuessWho[22415:4879262] [Purchases] - DEBUG: ℹ️ Offerings cache is stale, updating caches
2023-04-19 20:22:21.208737+0200 GuessWho[22415:4879499] [Purchases] - DEBUG: ℹ️ Network operation 'GetCustomerInfoOperation' found with the same cache key 'GetCustomerInfo...'. Skipping request.
2023-04-19 20:22:21.209069+0200 GuessWho[22415:4879499] [Purchases] - DEBUG: ℹ️ Network operation 'GetOfferingsOperation' found with the same cache key 'GetOfferingsOpe...'. Skipping request.
2023-04-19 20:22:21.581292+0200 GuessWho[22415:4879523] [Purchases] - DEBUG: ℹ️ API request completed: POST /v1/subscribers/$RCAnonymousID:7a9ea231e4e5468f80a05b65977361ce/adservices_attribution (200)
2023-04-19 20:22:21.581553+0200 GuessWho[22415:4879523] [Purchases] - DEBUG: ℹ️ AdServices attribution token successfully posted
2023-04-19 20:22:21.581593+0200 GuessWho[22415:4879523] [Purchases] - DEBUG: ℹ️ PostAdServicesTokenOperation: Finished
2023-04-19 20:22:21.581680+0200 GuessWho[22415:4879523] [Purchases] - DEBUG: ℹ️ Serial request done: POST subscribers/$RCAnonymousID%3A7a9ea231e4e5468f80a05b65977361ce/adservices_attribution, 0 requests left in the queue
2023-04-19 20:22:21.581880+0200 GuessWho[22415:4879499] [Purchases] - DEBUG: ℹ️ GetOfferingsOperation: Started
2023-04-19 20:22:21.582016+0200 GuessWho[22415:4879499] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request GET subscribers/$RCAnonymousID%3A7a9ea231e4e5468f80a05b65977361ce/offerings
2023-04-19 20:22:21.582698+0200 GuessWho[22415:4879499] [Purchases] - DEBUG: ℹ️ API request started: GET /v1/subscribers/$RCAnonymousID:7a9ea231e4e5468f80a05b65977361ce/offerings
2023-04-19 20:22:21.705121+0200 GuessWho[22415:4879501] [Purchases] - DEBUG: ℹ️ API request completed: GET /v1/subscribers/$RCAnonymousID:7a9ea231e4e5468f80a05b65977361ce/offerings (200)
2023-04-19 20:22:21.707698+0200 GuessWho[22415:4879501] [Purchases] - DEBUG: ℹ️ No existing products cached, starting store products request for: ["david.kadlcek.GuessWho.annualAccess", "david.kadlcek.GuessWho.annualAccessLimited", "david.kadlcek.GuessWho.monthlyAccess", "david.kadlcek.GuessWho.weeklyAccess"]
2023-04-19 20:22:21.707867+0200 GuessWho[22415:4879501] [Purchases] - DEBUG: ℹ️ Found an existing request for products: ["david.kadlcek.GuessWho.monthlyAccess", "david.kadlcek.GuessWho.annualAccess", "david.kadlcek.GuessWho.weeklyAccess", "david.kadlcek.GuessWho.annualAccessLimited"], appending to completion
2023-04-19 20:22:21.707936+0200 GuessWho[22415:4879501] [Purchases] - DEBUG: ℹ️ Found an existing request for products: ["david.kadlcek.GuessWho.annualAccess", "david.kadlcek.GuessWho.monthlyAccess", "david.kadlcek.GuessWho.annualAccessLimited", "david.kadlcek.GuessWho.weeklyAccess"], appending to completion
2023-04-19 20:22:21.707978+0200 GuessWho[22415:4879501] [Purchases] - DEBUG: ℹ️ GetOfferingsOperation: Finished
2023-04-19 20:22:21.708093+0200 GuessWho[22415:4879501] [Purchases] - DEBUG: ℹ️ Serial request done: GET subscribers/$RCAnonymousID%3A7a9ea231e4e5468f80a05b65977361ce/offerings, 0 requests left in the queue
2023-04-19 20:22:21.708352+0200 GuessWho[22415:4879504] [Purchases] - DEBUG: ℹ️ GetCustomerInfoOperation: Started
2023-04-19 20:22:21.708416+0200 GuessWho[22415:4879504] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request GET subscribers/$RCAnonymousID%3A7a9ea231e4e5468f80a05b65977361ce
2023-04-19 20:22:21.709433+0200 GuessWho[22415:4879504] [Purchases] - DEBUG: ℹ️ API request started: GET /v1/subscribers/$RCAnonymousID:7a9ea231e4e5468f80a05b65977361ce
2023-04-19 20:22:21.757896+0200 GuessWho[22415:4879504] [Purchases] - DEBUG: 😻 Store products request received response
2023-04-19 20:22:21.758021+0200 GuessWho[22415:4879504] [Purchases] - DEBUG: ℹ️ Store products request finished
2023-04-19 20:22:21.758904+0200 GuessWho[22415:4879504] [Purchases] - DEBUG: ℹ️ Package 'david.kadlcek.GuessWho.annualAccessLimited' in offering 'Limited' has a custom duration.
2023-04-19 20:22:21.759023+0200 GuessWho[22415:4879504] [Purchases] - DEBUG: ℹ️ Package 'david.kadlcek.GuessWho.annualAccessLimited' in offering 'Limited' has a custom duration.
2023-04-19 20:22:21.759093+0200 GuessWho[22415:4879504] [Purchases] - DEBUG: ℹ️ Package 'david.kadlcek.GuessWho.annualAccessLimited' in offering 'Limited' has a custom duration.
2023-04-19 20:22:21.759147+0200 GuessWho[22415:4879501] [Purchases] - DEBUG: ℹ️ No existing products cached, starting store products request for: ["david.kadlcek.GuessWho.annualAccess", "david.kadlcek.GuessWho.annualAccessLimited", "david.kadlcek.GuessWho.monthlyAccess", "david.kadlcek.GuessWho.weeklyAccess"]
2023-04-19 20:22:21.793591+0200 GuessWho[22415:4879523] [Purchases] - DEBUG: 😻 Store products request received response
2023-04-19 20:22:21.793673+0200 GuessWho[22415:4879523] [Purchases] - DEBUG: ℹ️ Store products request finished
2023-04-19 20:22:21.837429+0200 GuessWho[22415:4879503] [Purchases] - DEBUG: ℹ️ Caching trial or intro eligibility for products: ["david.kadlcek.GuessWho.annualAccessLimited", "david.kadlcek.GuessWho.weeklyAccess", "david.kadlcek.GuessWho.annualAccess", "david.kadlcek.GuessWho.monthlyAccess"]
2023-04-19 20:22:21.892607+0200 GuessWho[22415:4879523] [Purchases] - DEBUG: ℹ️ API request completed: GET /v1/subscribers/$RCAnonymousID:7a9ea231e4e5468f80a05b65977361ce (200)
2023-04-19 20:22:21.901225+0200 GuessWho[22415:4879523] [Purchases] - DEBUG: ℹ️ Sending latest CustomerInfo to delegate.
2023-04-19 20:22:21.901291+0200 GuessWho[22415:4879523] [Purchases] - DEBUG: 😻 CustomerInfo updated from network.
2023-04-19 20:22:21.901319+0200 GuessWho[22415:4879262] [Purchases] - DEBUG: ℹ️ Detected active subscriptions changed. Clearing trial or intro eligibility cache.
2023-04-19 20:22:21.901861+0200 GuessWho[22415:4879523] [Purchases] - DEBUG: 😻 CustomerInfo updated from network.
2023-04-19 20:22:21.902192+0200 GuessWho[22415:4879523] [Purchases] - DEBUG: 😻 CustomerInfo updated from network.
2023-04-19 20:22:21.902228+0200 GuessWho[22415:4879523] [Purchases] - DEBUG: ℹ️ GetCustomerInfoOperation: Finished
2023-04-19 20:22:21.902299+0200 GuessWho[22415:4879523] [Purchases] - DEBUG: ℹ️ Serial request done: GET subscribers/$RCAnonymousID%3A7a9ea231e4e5468f80a05b65977361ce, 0 requests left in the queue
2023-04-19 20:22:21.902328+0200 GuessWho[22415:4879501] [Purchases] - DEBUG: ℹ️ PostSubscriberAttributesOperation: Started
2023-04-19 20:22:21.902397+0200 GuessWho[22415:4879501] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request POST subscribers/$RCAnonymousID%3A7a9ea231e4e5468f80a05b65977361ce/attributes
2023-04-19 20:22:21.904138+0200 GuessWho[22415:4879501] [Purchases] - DEBUG: ℹ️ API request started: POST /v1/subscribers/$RCAnonymousID:7a9ea231e4e5468f80a05b65977361ce/attributes
2023-04-19 20:22:22.037048+0200 GuessWho[22415:4879504] [Purchases] - DEBUG: ℹ️ API request completed: POST /v1/subscribers/$RCAnonymousID:7a9ea231e4e5468f80a05b65977361ce/attributes (200)
2023-04-19 20:22:22.038446+0200 GuessWho[22415:4879504] [Purchases] - INFO: ℹ️ Marking attributes as synced for App User ID: $RCAnonymousID:7a9ea231e4e5468f80a05b65977361ce:
2023-04-19 20:22:22.038957+0200 GuessWho[22415:4879504] [Purchases] - DEBUG: ℹ️ Found 1 unsynced attributes for App User ID: $RCAnonymousID:7a9ea231e4e5468f80a05b65977361ce
2023-04-19 20:22:22.039188+0200 GuessWho[22415:4879504] [Purchases] - DEBUG: ℹ️ Unsynced attributes: ["$firebaseAppInstanceId": [SubscriberAttribute] key: $firebaseAppInstanceId value: 241CCECA552F467F9319747AF89D77E3 setTime: 2023-04-19 18:22:20 +0000]
4879504] [Purchases] - DEBUG: 😻 Subscriber attributes synced successfully for App User ID: $RCAnonymousID:7a9ea231e4e5468f80a05b65977361ce
2023-04-19 20:22:22.040968+0200 GuessWho[22415:4879504] [Purchases] - DEBUG: ℹ️ PostSubscriberAttributesOperation: Finished
2023-04-19 20:22:22.041556+0200 GuessWho[22415:4879504] [Purchases] - DEBUG: ℹ️ Serial request done: POST subscribers/$RCAnonymousID%3A7a9ea231e4e5468f80a05b65977361ce/attributes, 0 requests left in the queue
2023-04-19 20:22:23.295697+0200 GuessWho[22415:4879262] [Purchases] - DEBUG: ℹ️ applicationDidBecomeActive
2023-04-19 20:22:30.213059+0200 GuessWho[22415:4879262] [Purchases] - INFO: 💰 Purchasing Product 'david.kadlcek.GuessWho.annualAccess'
2023-04-19 20:22:38.526917+0200 GuessWho[22415:4879262] [Purchases] - DEBUG: ℹ️ applicationDidBecomeActive
2023-04-19 20:22:38.559180+0200 GuessWho[22415:4879503] [Purchases] - WARN: 🍎⚠️ StoreKit 2 purchase took longer than expected (8.34 seconds)
2023-04-19 20:22:38.568002+0200 GuessWho[22415:4879503] [Purchases] - DEBUG: ℹ️ Force refreshing the receipt to get latest transactions from Apple.
2023-04-19 20:22:38.568141+0200 GuessWho[22415:4879503] [Purchases] - DEBUG: ℹ️ SKReceiptRefreshRequest started
2023-04-19 20:22:39.475313+0200 GuessWho[22415:4879262] [Purchases] - DEBUG: ℹ️ SKReceiptRefreshRequest finished
2023-04-19 20:22:39.476761+0200 GuessWho[22415:4879262] [Purchases] - DEBUG: ℹ️ Loaded receipt from url file:///private/var/mobile/Containers/Data/Application/AAB42E94-444F-44E5-8166-F3C64CE4811E/StoreKit/sandboxReceipt
2023-04-19 20:22:39.476984+0200 GuessWho[22415:4879262] [Purchases] - DEBUG: ℹ️ Skipping products request for these products because they were already cached: ["david.kadlcek.GuessWho.annualAccess"]
2023-04-19 20:22:39.478553+0200 GuessWho[22415:4879262] [Purchases] - DEBUG: ℹ️ Found 0 unsynced attributes for App User ID: $RCAnonymousID:7a9ea231e4e5468f80a05b65977361ce
2023-04-19 20:22:39.493964+0200 GuessWho[22415:4879646] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Started
2023-04-19 20:22:39.494199+0200 GuessWho[22415:4879646] [Purchases] - INFO: ℹ️ Parsing receipt
2023-04-19 20:22:39.499366+0200 GuessWho[22415:4879646] [Purchases] - INFO: ℹ️ Receipt parsed successfully
2023-04-19 20:22:39.500883+0200 GuessWho[22415:4879646] [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-19 20:22:39.501266+0200 GuessWho[22415:4879646] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request POST receipts
2023-04-19 20:22:39.504004+0200 GuessWho[22415:4879646] [Purchases] - DEBUG: ℹ️ API request started: POST /v1/receipts
2023-04-19 20:22:40.472880+0200 GuessWho[22415:4879646] [Purchases] - DEBUG: ℹ️ API request completed: POST /v1/receipts (200)
2023-04-19 20:22:40.490938+0200 GuessWho[22415:4879646] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Finished
2023-04-19 20:22:40.491197+0200 GuessWho[22415:4879646] [Purchases] - DEBUG: ℹ️ Serial request done: POST receipts, 0 requests left in the queue
2023-04-19 20:22:40.498789+0200 GuessWho[22415:4879262] [Purchases] - DEBUG: ℹ️ Sending updated CustomerInfo to delegate.
2023-04-19 20:22:40.498947+0200 GuessWho[22415:4879262] [Purchases] - DEBUG: ℹ️ Detected active subscriptions changed. Clearing trial or intro eligibility cache.
2023-04-19 20:22:40.499055+0200 GuessWho[22415:4879262] [Purchases] - INFO: 💰 Finishing transaction '2000000316395064' for product 'david.kadlcek.GuessWho.annualAccess'
2023-04-19 20:22:41.169436+0200 GuessWho[22415:4879646] [Purchases] - INFO: 😻💰 Purchased product - 'david.kadlcek.GuessWho.annualAccess'

Will it work for people with iOS < 15?

@NachoSoto
Copy link
Contributor

NachoSoto commented Apr 19, 2023

It won't. Can you share those same verbose log but with StoreKit 2 disabled? 🙏🏻
We'll get this fixed with StoreKit 1 💪🏻 I think we're getting close to figuring out the problem.

I'm looking at the code and I believe it's somewhere in StoreKit1Wrapper's SKPaymentTransactionObserver implementation, somehow not finding the callback in finishedTransactionCallbacks, but those verbose logs might help.

@DavidKadlcek
Copy link
Author

2023-04-19 20:26:28.457717+0200 GuessWho[22431:4882939] [Purchases] - VERBOSE: StoreKit1Wrapper.init: StoreKit1Wrapper (0x0000000282f74060)
2023-04-19 20:26:28.457868+0200 GuessWho[22431:4882939] [Purchases] - DEBUG: ℹ️ Configuring SDK using RevenueCat's UserDefaults suite.
2023-04-19 20:26:28.459001+0200 GuessWho[22431:4882939] [Purchases] - VERBOSE: DeviceCache.init: DeviceCache (0x0000000282f74840)
2023-04-19 20:26:28.459673+0200 GuessWho[22431:4882939] [Purchases] - DEBUG: 👤 Identifying App User ID
2023-04-19 20:26:28.463429+0200 GuessWho[22431:4882939] [Purchases] - DEBUG: ℹ️ Debug logging enabled
2023-04-19 20:26:28.463504+0200 GuessWho[22431:4882939] [Purchases] - DEBUG: ℹ️ SDK Version - 4.17.10
2023-04-19 20:26:28.463536+0200 GuessWho[22431:4882939] [Purchases] - DEBUG: ℹ️ Bundle ID - david.kadlcek.GuessWho
2023-04-19 20:26:28.466397+0200 GuessWho[22431:4882939] [Purchases] - DEBUG: ℹ️ System Version - Version 16.3.1 (Build 20D67)
2023-04-19 20:26:28.466438+0200 GuessWho[22431:4882939] [Purchases] - DEBUG: ℹ️ Not using a simulator.
2023-04-19 20:26:28.466465+0200 GuessWho[22431:4882939] [Purchases] - DEBUG: 👤 No initial App User ID
2023-04-19 20:26:28.467802+0200 GuessWho[22431:4882939] [Purchases] - VERBOSE: Purchases.init: created new Purchases instance: Purchases (0x00000002832687e0)
2023-04-19 20:26:28.478179+0200 GuessWho[22431:4882939] [Purchases] - DEBUG: ℹ️ setting reserved attribute: $firebaseAppInstanceId
2023-04-19 20:26:28.483877+0200 GuessWho[22431:4882939] [Purchases] - DEBUG: ℹ️ No cached Offerings, fetching from network
2023-04-19 20:26:28.489279+0200 GuessWho[22431:4882939] [Purchases] - DEBUG: ℹ️ Vending CustomerInfo from cache.
2023-04-19 20:26:28.728370+0200 GuessWho[22431:4883160] [Purchases] - DEBUG: ℹ️ Network operation 'GetOfferingsOperation' found with the same cache key 'GetOfferingsOpe...'. Skipping request.
2023-04-19 20:26:28.728554+0200 GuessWho[22431:4883156] [Purchases] - DEBUG: ℹ️ GetOfferingsOperation: Started
2023-04-19 20:26:28.728718+0200 GuessWho[22431:4883156] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request GET subscribers/$RCAnonymousID%3Ac1e50d599ac3464b921f3f368e1cbb72/offerings
2023-04-19 20:26:28.731140+0200 GuessWho[22431:4882939] [Purchases] - DEBUG: ℹ️ applicationDidBecomeActive
2023-04-19 20:26:28.732940+0200 GuessWho[22431:4882939] [Purchases] - DEBUG: ℹ️ Offerings cache is stale, updating caches
2023-04-19 20:26:28.733587+0200 GuessWho[22431:4883171] [Purchases] - DEBUG: ℹ️ Network operation 'GetOfferingsOperation' found with the same cache key 'GetOfferingsOpe...'. Skipping request.
2023-04-19 20:26:28.741630+0200 GuessWho[22431:4883156] [Purchases] - DEBUG: ℹ️ API request started: GET /v1/subscribers/$RCAnonymousID:c1e50d599ac3464b921f3f368e1cbb72/offerings
2023-04-19 20:26:29.195338+0200 GuessWho[22431:4883155] [Purchases] - DEBUG: ℹ️ API request completed: GET /v1/subscribers/$RCAnonymousID:c1e50d599ac3464b921f3f368e1cbb72/offerings (200)
2023-04-19 20:26:29.196766+0200 GuessWho[22431:4883155] [Purchases] - DEBUG: ℹ️ No existing products cached, starting store products request for: ["david.kadlcek.GuessWho.monthlyAccess", "david.kadlcek.GuessWho.annualAccess", "david.kadlcek.GuessWho.weeklyAccess", "david.kadlcek.GuessWho.annualAccessLimited"]
2023-04-19 20:26:29.196880+0200 GuessWho[22431:4883155] [Purchases] - DEBUG: ℹ️ Found an existing request for products: ["david.kadlcek.GuessWho.annualAccessLimited", "david.kadlcek.GuessWho.monthlyAccess", "david.kadlcek.GuessWho.weeklyAccess", "david.kadlcek.GuessWho.annualAccess"], appending to completion
2023-04-19 20:26:29.196932+0200 GuessWho[22431:4883155] [Purchases] - DEBUG: ℹ️ Found an existing request for products: ["david.kadlcek.GuessWho.annualAccess", "david.kadlcek.GuessWho.weeklyAccess", "david.kadlcek.GuessWho.annualAccessLimited", "david.kadlcek.GuessWho.monthlyAccess"], appending to completion
2023-04-19 20:26:29.196959+0200 GuessWho[22431:4883155] [Purchases] - DEBUG: ℹ️ GetOfferingsOperation: Finished
2023-04-19 20:26:29.197024+0200 GuessWho[22431:4883155] [Purchases] - DEBUG: ℹ️ Serial request done: GET subscribers/$RCAnonymousID%3Ac1e50d599ac3464b921f3f368e1cbb72/offerings, 0 requests left in the queue
2023-04-19 20:26:29.197137+0200 GuessWho[22431:4883159] [Purchases] - DEBUG: ℹ️ No existing products cached, starting store products request for: ["david.kadlcek.GuessWho.monthlyAccess", "david.kadlcek.GuessWho.annualAccess", "david.kadlcek.GuessWho.weeklyAccess", "david.kadlcek.GuessWho.annualAccessLimited"]
2023-04-19 20:26:29.197190+0200 GuessWho[22431:4883173] [Purchases] - DEBUG: ℹ️ GetCustomerInfoOperation: Started
2023-04-19 20:26:29.197331+0200 GuessWho[22431:4883173] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request GET subscribers/$RCAnonymousID%3Ac1e50d599ac3464b921f3f368e1cbb72
2023-04-19 20:26:29.199220+0200 GuessWho[22431:4883173] [Purchases] - DEBUG: ℹ️ API request started: GET /v1/subscribers/$RCAnonymousID:c1e50d599ac3464b921f3f368e1cbb72
2023-04-19 20:26:29.234824+0200 GuessWho[22431:4883173] [Purchases] - DEBUG: 😻 Store products request received response
2023-04-19 20:26:29.234837+0200 GuessWho[22431:4883159] [Purchases] - DEBUG: 😻 Store products request finished
2023-04-19 20:26:29.236008+0200 GuessWho[22431:4883173] [Purchases] - DEBUG: ℹ️ Package 'david.kadlcek.GuessWho.annualAccessLimited' in offering 'Limited' has a custom duration.
2023-04-19 20:26:29.236127+0200 GuessWho[22431:4883173] [Purchases] - DEBUG: ℹ️ Package 'david.kadlcek.GuessWho.annualAccessLimited' in offering 'Limited' has a custom duration.
2023-04-19 20:26:29.236190+0200 GuessWho[22431:4883173] [Purchases] - DEBUG: ℹ️ Package 'david.kadlcek.GuessWho.annualAccessLimited' in offering 'Limited' has a custom duration.
2023-04-19 20:26:29.314263+0200 GuessWho[22431:4883173] [Purchases] - DEBUG: ℹ️ API request completed: GET /v1/subscribers/$RCAnonymousID:c1e50d599ac3464b921f3f368e1cbb72 (200)
2023-04-19 20:26:29.317843+0200 GuessWho[22431:4883173] [Purchases] - DEBUG: ℹ️ Sending latest CustomerInfo to delegate.
2023-04-19 20:26:29.317898+0200 GuessWho[22431:4883173] [Purchases] - DEBUG: 😻 CustomerInfo updated from network.
2023-04-19 20:26:29.317940+0200 GuessWho[22431:4883173] [Purchases] - DEBUG: ℹ️ GetCustomerInfoOperation: Finished
2023-04-19 20:26:29.318151+0200 GuessWho[22431:4883173] [Purchases] - DEBUG: ℹ️ Serial request done: GET subscribers/$RCAnonymousID%3Ac1e50d599ac3464b921f3f368e1cbb72, 0 requests left in the queue
2023-04-19 20:26:29.999605+0200 GuessWho[22431:4882939] [Purchases] - WARN: 🍎‼️ Unable to load receipt, ensure you are logged in to a valid Apple account.
2023-04-19 20:26:29.999705+0200 GuessWho[22431:4882939] [Purchases] - DEBUG: ℹ️ Skipping products request for these products because they were already cached: ["david.kadlcek.GuessWho.weeklyAccess", "david.kadlcek.GuessWho.annualAccessLimited", "david.kadlcek.GuessWho.annualAccess", "david.kadlcek.GuessWho.monthlyAccess"]
2023-04-19 20:26:30.010583+0200 GuessWho[22431:4882939] [Purchases] - DEBUG: ℹ️ Detected active subscriptions changed. Clearing trial or intro eligibility cache.
2023-04-19 20:26:30.010610+0200 GuessWho[22431:4883173] [Purchases] - DEBUG: ℹ️ GetIntroEligibilityOperation: Started
2023-04-19 20:26:30.010707+0200 GuessWho[22431:4883173] [Purchases] - WARN: 🍎‼️ App running on sandbox without a receipt file. Unable to determine into eligibility unless you've purchased before and there is a receipt available.
2023-04-19 20:26:30.010894+0200 GuessWho[22431:4883173] [Purchases] - DEBUG: ℹ️ GetIntroEligibilityOperation: Finished
2023-04-19 20:26:30.011352+0200 GuessWho[22431:4882939] [Purchases] - DEBUG: ℹ️ Caching trial or intro eligibility for products: ["david.kadlcek.GuessWho.weeklyAccess", "david.kadlcek.GuessWho.monthlyAccess"]
2023-04-19 20:26:35.436449+0200 GuessWho[22431:4882939] [Purchases] - INFO: 💰 Purchasing Product 'david.kadlcek.GuessWho.annualAccess'
2023-04-19 20:26:35.442200+0200 GuessWho[22431:4883173] [Purchases] - DEBUG: ℹ️ StoreKit1Wrapper (0x0000000282f74060) updatedTransaction: david.kadlcek.GuessWho.annualAccess 0
2023-04-19 20:26:35.443663+0200 GuessWho[22431:4883173] [Purchases] - VERBOSE: The SKPaymentTransaction has a nil value for transaction date - this is a bug in StoreKit.
2023-04-19 20:26:35.443883+0200 GuessWho[22431:4883173] [Purchases] - VERBOSE: The SKPaymentTransaction has a nil value for transaction identifier - this is a bug in StoreKit.
2023-04-19 20:26:43.640163+0200 GuessWho[22431:4882939] [Purchases] - DEBUG: ℹ️ applicationDidBecomeActive
2023-04-19 20:26:43.648615+0200 GuessWho[22431:4883260] [Purchases] - DEBUG: ℹ️ StoreKit1Wrapper (0x0000000282f74060) updatedTransaction: david.kadlcek.GuessWho.annualAccess 2000000316396907 2000000316384629 1
2023-04-19 20:26:43.663992+0200 GuessWho[22431:4883260] [Purchases] - DEBUG: ℹ️ Force refreshing the receipt to get latest transactions from Apple.
2023-04-19 20:26:43.664130+0200 GuessWho[22431:4883260] [Purchases] - DEBUG: ℹ️ SKReceiptRefreshRequest started
2023-04-19 20:26:44.202911+0200 GuessWho[22431:4883155] [Purchases] - DEBUG: ℹ️ StoreKit1Wrapper (0x0000000282f74060) removedTransaction: david.kadlcek.GuessWho.annualAccess 2000000316396907 2000000316384629 1
2023-04-19 20:26:44.228511+0200 GuessWho[22431:4882939] [Purchases] - DEBUG: ℹ️ SKReceiptRefreshRequest finished
2023-04-19 20:26:44.228983+0200 GuessWho[22431:4882939] [Purchases] - DEBUG: ℹ️ Loaded receipt from url file:///private/var/mobile/Containers/Data/Application/E9BB0577-0C64-411F-95B1-627F277844EA/StoreKit/sandboxReceipt
2023-04-19 20:26:44.229113+0200 GuessWho[22431:4882939] [Purchases] - DEBUG: ℹ️ Skipping products request for these products because they were already cached: ["david.kadlcek.GuessWho.annualAccess"]
2023-04-19 20:26:44.230159+0200 GuessWho[22431:4882939] [Purchases] - DEBUG: ℹ️ Found 0 unsynced attributes for App User ID: $RCAnonymousID:c1e50d599ac3464b921f3f368e1cbb72
2023-04-19 20:26:44.245780+0200 GuessWho[22431:4883155] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Started
2023-04-19 20:26:44.245980+0200 GuessWho[22431:4883155] [Purchases] - INFO: ℹ️ Parsing receipt
2023-04-19 20:26:44.249850+0200 GuessWho[22431:4883155] [Purchases] - INFO: ℹ️ Receipt parsed successfully
2023-04-19 20:26:44.251445+0200 GuessWho[22431:4883155] [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-19 20:26:44.251814+0200 GuessWho[22431:4883155] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request POST receipts
2023-04-19 20:26:44.255591+0200 GuessWho[22431:4883155] [Purchases] - DEBUG: ℹ️ API request started: POST /v1/receipts
2023-04-19 20:26:45.385290+0200 GuessWho[22431:4883259] [Purchases] - DEBUG: ℹ️ API request completed: POST /v1/receipts (200)
2023-04-19 20:26:45.404560+0200 GuessWho[22431:4883259] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Finished
2023-04-19 20:26:45.404869+0200 GuessWho[22431:4883259] [Purchases] - DEBUG: ℹ️ Serial request done: POST receipts, 0 requests left in the queue
2023-04-19 20:26:45.413828+0200 GuessWho[22431:4882939] [Purchases] - DEBUG: ℹ️ Sending updated CustomerInfo to delegate.
2023-04-19 20:26:45.413959+0200 GuessWho[22431:4882939] [Purchases] - DEBUG: ℹ️ Detected active subscriptions changed. Clearing trial or intro eligibility cache.
2023-04-19 20:26:45.414038+0200 GuessWho[22431:4882939] [Purchases] - INFO: 💰 Finishing transaction '2000000316396907' for product 'david.kadlcek.GuessWho.annualAccess'

@NachoSoto
Copy link
Contributor

NachoSoto commented Apr 19, 2023

I'm looking into this. The root of the problem is that StoreKit is notifying the SDK that the transaction was removed before finishing the transaction:

StoreKit1Wrapper (0x0000000282f74060) removedTransaction: david.kadlcek.GuessWho.annualAccess 2000000316396907 2000000316384629 1

Which is not normal behavior. It makes sense that that this does not reproduce in production, and not very surprised it's happening on sandbox. But we'll obviously need to figure out the reason and/or work around it. Thanks again for the very detailed report, we'll have a fix soon 👌🏻

@DavidKadlcek
Copy link
Author

Will be a new version available soon (in 2 days)? Is it safe to release the version now to the AppStore?

@NachoSoto
Copy link
Contributor

Now that we know it's a StoreKit issue, and if you're not able to reproduce on the App Store version, I'd say it's safe.
As for when we'll have a fix for this, I can't really say right now, but we'll keep you posted.

@NachoSoto
Copy link
Contributor

NachoSoto commented Apr 19, 2023

@DavidKadlcek is this happening with or without .storekit files?

It would also be helpful if you can click "Debug -> StoreKit -> Manage Transactions" and send us the list of transactions there after you reproduce:
Screenshot 2023-04-19 at 12 29 07

@DavidKadlcek
Copy link
Author

I sent you physical device. Also I tried it in simulator and I saw transaction completed inside the Manage Transactions. Btw. the physical device works earlier. Why is not working anymore now? What changed?

@NachoSoto
Copy link
Contributor

I wonder if this is an iOS 16.3 regression?

@DavidKadlcek
Copy link
Author

DavidKadlcek commented Apr 19, 2023

I tried to run it on the simulator with iOS 14.0 and .storekit file -> it is not working. Also am I the only one who doesn't work it? If so, why? 😄

NachoSoto added a commit that referenced this issue Apr 19, 2023
…llbacks to notify

This would make issues like #2415 easier to debug.
NachoSoto added a commit that referenced this issue Apr 20, 2023
…o callbacks to notify (#2418)

This would make issues like #2415 easier to debug.
@NachoSoto
Copy link
Contributor

@DavidKadlcek apologies if I already asked but I couldn't find your answer: are you able to reproduce this with a brand new sandbox account? Make sure to also remove the user / anonymous user from the RevenueCat dashboard as well to ensure a clean state.

@DavidKadlcek
Copy link
Author

@NachoSoto yes, it is happening on the newly created sandbox account too

NachoSoto added a commit that referenced this issue Apr 26, 2023
…o callbacks to notify (#2418)

This would make issues like #2415 easier to debug.
@DavidKadlcek
Copy link
Author

@NachoSoto Any progress?

@NachoSoto
Copy link
Contributor

We shipped an update (4.18.0) with a couple of new debug logs to help debug this. Would you mind trying to reproduce it with it and sending us the new logs? 🙏

@DavidKadlcek
Copy link
Author

@NachoSoto

2023-05-01 19:32:08.285113+0200 GuessWho[33315:2943187] [Purchases] - VERBOSE: StoreKit1Wrapper.init: StoreKit1Wrapper (0x000000028265f780)
2023-05-01 19:32:08.285314+0200 GuessWho[33315:2943187] [Purchases] - DEBUG: ℹ️ Configuring SDK using RevenueCat's UserDefaults suite.
2023-05-01 19:32:08.287314+0200 GuessWho[33315:2943187] [Purchases] - VERBOSE: DeviceCache.init: DeviceCache (0x00000002826561c0)
2023-05-01 19:32:08.288296+0200 GuessWho[33315:2943187] [Purchases] - DEBUG: 👤 Identifying App User ID
2023-05-01 19:32:08.294075+0200 GuessWho[33315:2943187] [Purchases] - DEBUG: ℹ️ Debug logging enabled
2023-05-01 19:32:08.294188+0200 GuessWho[33315:2943187] [Purchases] - DEBUG: ℹ️ SDK Version - 4.18.0
315:2943187] [Purchases] - DEBUG: ℹ️ Bundle ID - david.kadlcek.GuessWho
2023-05-01 19:32:08.296223+0200 GuessWho[33315:2943187] [Purchases] - DEBUG: ℹ️ System Version - Version 16.4.1 (Build 20E252)
2023-05-01 19:32:08.296278+0200 GuessWho[33315:2943187] [Purchases] - DEBUG: ℹ️ Not using a simulator.
2023-05-01 19:32:08.296311+0200 GuessWho[33315:2943187] [Purchases] - DEBUG: 👤 No initial App User ID
2023-05-01 19:32:08.298528+0200 GuessWho[33315:2943187] [Purchases] - VERBOSE: Purchases.init: created new Purchases instance: Purchases (0x0000000283b50620)
2023-05-01 19:32:08.311024+0200 GuessWho[33315:2943187] [Purchases] - DEBUG: ℹ️ setting reserved attribute: $firebaseAppInstanceId
2023-05-01 19:32:08.313109+0200 GuessWho[33315:2943187] [Purchases] - DEBUG: ℹ️ No cached Offerings, fetching from network
2023-05-01 19:32:08.318782+0200 GuessWho[33315:2943187] [Purchases] - DEBUG: ℹ️ Vending CustomerInfo from cache.
2023-05-01 19:32:08.945978+0200 GuessWho[33315:2943359] [Purchases] - DEBUG: ℹ️ GetOfferingsOperation: Started
2023-05-01 19:32:08.945986+0200 GuessWho[33315:2943367] [Purchases] - DEBUG: ℹ️ Network operation 'GetOfferingsOperation' found with the same cache key 'GetOfferingsOpe...'. Skipping request.
2023-05-01 19:32:08.946305+0200 GuessWho[33315:2943359] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request GET subscribers/$RCAnonymousID%3A6b17dc092a1b4e5e8fb9b5424f6aff66/offerings
2023-05-01 19:32:08.949912+0200 GuessWho[33315:2943187] [Purchases] - DEBUG: ℹ️ applicationDidBecomeActive
2023-05-01 19:32:08.952938+0200 GuessWho[33315:2943390] [Purchases] - DEBUG: ℹ️ Network operation 'GetOfferingsOperation' found with the same cache key 'GetOfferingsOpe...'. Skipping request.
uessWho[33315:2943359] [Purchases] - DEBUG: ℹ️ API request started: GET /v1/subscribers/$RCAnonymousID:6b17dc092a1b4e5e8fb9b5424f6aff66/offerings
2023-05-01 19:32:09.520135+0200 GuessWho[33315:2943367] [Purchases] - DEBUG: ℹ️ API request completed: GET /v1/subscribers/$RCAnonymousID:6b17dc092a1b4e5e8fb9b5424f6aff66/offerings (200)
2023-05-01 19:32:09.521813+0200 GuessWho[33315:2943367] [Purchases] - DEBUG: ℹ️ No existing products cached, starting store products request for: ["david.kadlcek.GuessWho.annualAccessLimited", "david.kadlcek.GuessWho.weeklyAccess", "david.kadlcek.GuessWho.monthlyAccess", "david.kadlcek.GuessWho.annualAccess"]
2023-05-01 19:32:09.521899+0200 GuessWho[33315:2943367] [Purchases] - DEBUG: ℹ️ Found an existing request for products: ["david.kadlcek.GuessWho.annualAccessLimited", "david.kadlcek.GuessWho.weeklyAccess", "david.kadlcek.GuessWho.monthlyAccess", "david.kadlcek.GuessWho.annualAccess"], appending to completion
2023-05-01 19:32:09.522110+0200 GuessWho[33315:2943367] [Purchases] - DEBUG: ℹ️ Found an existing request for products: ["david.kadlcek.GuessWho.annualAccessLimited", "david.kadlcek.GuessWho.monthlyAccess", "david.kadlcek.GuessWho.annualAccess", "david.kadlcek.GuessWho.weeklyAccess"], appending to completion
2023-05-01 19:32:09.522101+0200 GuessWho[33315:2943358] [Purchases] - DEBUG: ℹ️ No existing products cached, starting store products request for: ["david.kadlcek.GuessWho.annualAccessLimited", "david.kadlcek.GuessWho.weeklyAccess", "david.kadlcek.GuessWho.monthlyAccess", "david.kadlcek.GuessWho.annualAccess"]
2023-05-01 19:32:09.522166+0200 GuessWho[33315:2943367] [Purchases] - DEBUG: ℹ️ GetOfferingsOperation: Finished
2023-05-01 19:32:09.522233+0200 GuessWho[33315:2943367] [Purchases] - DEBUG: ℹ️ Serial request done: GET subscribers/$RCAnonymousID%3A6b17dc092a1b4e5e8fb9b5424f6aff66/offerings, 0 requests left in the queue
2023-05-01 19:32:09.522350+0200 GuessWho[33315:2943368] [Purchases] - DEBUG: ℹ️ GetCustomerInfoOperation: Started
2023-05-01 19:32:09.522544+0200 GuessWho[33315:2943368] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request GET subscribers/$RCAnonymousID%3A6b17dc092a1b4e5e8fb9b5424f6aff66
2023-05-01 19:32:09.523222+0200 GuessWho[33315:2943368] [Purchases] - DEBUG: ℹ️ API request started: GET /v1/subscribers/$RCAnonymousID:6b17dc092a1b4e5e8fb9b5424f6aff66
2023-05-01 19:32:09.570983+0200 GuessWho[33315:2943368] [Purchases] - DEBUG: 😻 Store products request finished
2023-05-01 19:32:09.570999+0200 GuessWho[33315:2943358] [Purchases] - DEBUG: 😻 Store products request received response
2023-05-01 19:32:09.571876+0200 GuessWho[33315:2943358] [Purchases] - DEBUG: ℹ️ Package 'david.kadlcek.GuessWho.annualAccessLimited' in offering 'Limited' has a custom duration.
2023-05-01 19:32:09.571998+0200 GuessWho[33315:2943358] [Purchases] - DEBUG: ℹ️ Package 'david.kadlcek.GuessWho.annualAccessLimited' in offering 'Limited' has a custom duration.
2023-05-01 19:32:09.572058+0200 GuessWho[33315:2943358] [Purchases] - DEBUG: ℹ️ Package 'david.kadlcek.GuessWho.annualAccessLimited' in offering 'Limited' has a custom duration.
2023-05-01 19:32:09.638601+0200 GuessWho[33315:2943368] [Purchases] - DEBUG: ℹ️ API request completed: GET /v1/subscribers/$RCAnonymousID:6b17dc092a1b4e5e8fb9b5424f6aff66 (200)
2023-05-01 19:32:09.642653+0200 GuessWho[33315:2943368] [Purchases] - DEBUG: ℹ️ Sending latest CustomerInfo to delegate.
2023-05-01 19:32:09.642706+0200 GuessWho[33315:2943368] [Purchases] - DEBUG: 😻 CustomerInfo updated from network.
2023-05-01 19:32:09.642759+0200 GuessWho[33315:2943368] [Purchases] - DEBUG: ℹ️ GetCustomerInfoOperation: Finished
2023-05-01 19:32:09.642809+0200 GuessWho[33315:2943368] [Purchases] - DEBUG: ℹ️ Serial request done: GET subscribers/$RCAnonymousID%3A6b17dc092a1b4e5e8fb9b5424f6aff66, 0 requests left in the queue
2023-05-01 19:32:10.161721+0200 GuessWho[33315:2943187] [Purchases] - WARN: 🍎‼️ Unable to load receipt, ensure you are logged in to a valid Apple account.
2023-05-01 19:32:10.161809+0200 GuessWho[33315:2943187] [Purchases] - DEBUG: ℹ️ Skipping products request for these products because they were already cached: ["david.kadlcek.GuessWho.annualAccess", "david.kadlcek.GuessWho.monthlyAccess", "david.kadlcek.GuessWho.weeklyAccess", "david.kadlcek.GuessWho.annualAccessLimited"]
2023-05-01 19:32:10.170597+0200 GuessWho[33315:2943187] [Purchases] - DEBUG: ℹ️ Detected active subscriptions changed. Clearing trial or intro eligibility cache.
2023-05-01 19:32:10.170629+0200 GuessWho[33315:2943368] [Purchases] - DEBUG: ℹ️ GetIntroEligibilityOperation: Started
2023-05-01 19:32:10.170755+0200 GuessWho[33315:2943368] [Purchases] - WARN: 🍎‼️ App running on sandbox without a receipt file. Unable to determine into eligibility unless you've purchased before and there is a receipt available.
2023-05-01 19:32:10.170797+0200 GuessWho[33315:2943368] [Purchases] - DEBUG: ℹ️ GetIntroEligibilityOperation: Finished
2023-05-01 19:32:10.171398+0200 GuessWho[33315:2943187] [Purchases] - DEBUG: ℹ️ Caching trial or intro eligibility for products: ["david.kadlcek.GuessWho.weeklyAccess", "david.kadlcek.GuessWho.monthlyAccess"]
2023-05-01 19:32:17.148292+0200 GuessWho[33315:2943187] [Purchases] - INFO: 💰 Purchasing Product 'david.kadlcek.GuessWho.annualAccess'
2023-05-01 19:32:17.154537+0200 GuessWho[33315:2943187] [Purchases] - DEBUG: ℹ️ Adding payment for product 'david.kadlcek.GuessWho.annualAccess'. 0 transactions already in the queue.
2023-05-01 19:32:17.156327+0200 GuessWho[33315:2943387] [Purchases] - DEBUG: ℹ️ StoreKit1Wrapper (0x000000028265f780) updatedTransaction: david.kadlcek.GuessWho.annualAccess 0
2023-05-01 19:32:17.156621+0200 GuessWho[33315:2943387] [Purchases] - VERBOSE: The SKPaymentTransaction has a nil value for transaction date - this is a bug in StoreKit.
2023-05-01 19:32:17.156719+0200 GuessWho[33315:2943387] [Purchases] - VERBOSE: The SKPaymentTransaction has a nil value for transaction identifier - this is a bug in StoreKit.
2023-05-01 19:32:35.187553+0200 GuessWho[33315:2943187] [Purchases] - DEBUG: ℹ️ applicationDidBecomeActive
2023-05-01 19:32:51.168919+0200 GuessWho[33315:2943951] [Purchases] - DEBUG: ℹ️ StoreKit1Wrapper (0x000000028265f780) updatedTransaction: david.kadlcek.GuessWho.annualAccess 2000000323180005 2000000077648060 1
2023-05-01 19:32:51.231650+0200 GuessWho[33315:2943951] [Purchases] - DEBUG: ℹ️ Force refreshing the receipt to get latest transactions from Apple.
2023-05-01 19:32:51.231746+0200 GuessWho[33315:2943951] [Purchases] - DEBUG: ℹ️ SKReceiptRefreshRequest started
2023-05-01 19:32:51.232966+0200 GuessWho[33315:2943187] [Purchases] - DEBUG: ℹ️ applicationDidBecomeActive
2023-05-01 19:32:51.735774+0200 GuessWho[33315:2943596] [Purchases] - DEBUG: ℹ️ StoreKit1Wrapper (0x000000028265f780) removedTransaction: david.kadlcek.GuessWho.annualAccess 2000000323180005 2000000077648060 1
2023-05-01 19:32:51.735967+0200 GuessWho[33315:2943596] [Purchases] - DEBUG: ℹ️ StoreKit1Wrapper (0x000000028265f780) removedTransaction for (david.kadlcek.GuessWho.annualAccess but not callbacks to notify
2023-05-01 19:32:51.986297+0200 GuessWho[33315:2943187] [Purchases] - DEBUG: ℹ️ SKReceiptRefreshRequest finished
2023-05-01 19:32:51.986630+0200 GuessWho[33315:2943187] [Purchases] - DEBUG: ℹ️ Loaded receipt from url file:///private/var/mobile/Containers/Data/Application/FA9E2F51-1604-4592-A901-5EAA10F751D3/StoreKit/sandboxReceipt
2023-05-01 19:32:51.986717+0200 GuessWho[33315:2943187] [Purchases] - DEBUG: ℹ️ Skipping products request for these products because they were already cached: ["david.kadlcek.GuessWho.annualAccess"]
2023-05-01 19:32:51.987072+0200 GuessWho[33315:2943187] [Purchases] - DEBUG: ℹ️ Found 0 unsynced attributes for App User ID: $RCAnonymousID:6b17dc092a1b4e5e8fb9b5424f6aff66
2023-05-01 19:32:51.995264+0200 GuessWho[33315:2943596] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Started
2023-05-01 19:32:51.995701+0200 GuessWho[33315:2943596] [Purchases] - INFO: ℹ️ Parsing receipt
2023-05-01 19:32:52.055346+0200 GuessWho[33315:2943596] [Purchases] - INFO: ℹ️ Receipt parsed successfully
2023-05-01 19:32:52.061799+0200 GuessWho[33315:2943596] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Posting receipt (note: the contents might not be up-to-date, but it will be refreshed with Apple's servers):
2023-05-01 19:32:52.062845+0200 GuessWho[33315:2943596] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request POST receipts
2023-05-01 19:32:52.065760+0200 GuessWho[33315:2943596] [Purchases] - DEBUG: ℹ️ API request started: POST /v1/receipts
2023-05-01 19:32:55.114223+0200 GuessWho[33315:2943952] [Purchases] - DEBUG: ℹ️ API request completed: POST /v1/receipts (200)
2023-05-01 19:32:55.133172+0200 GuessWho[33315:2943952] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Finished
2023-05-01 19:32:55.133443+0200 GuessWho[33315:2943952] [Purchases] - DEBUG: ℹ️ Serial request done: POST receipts, 0 requests left in the queue
2023-05-01 19:32:55.140993+0200 GuessWho[33315:2943187] [Purchases] - DEBUG: ℹ️ Sending updated CustomerInfo to delegate.
2023-05-01 19:32:55.141174+0200 GuessWho[33315:2943187] [Purchases] - INFO: 💰 Finishing transaction '2000000323180005' for product 'david.kadlcek.GuessWho.annualAccess'
2023-05-01 19:32:55.141420+0200 GuessWho[33315:2943187] [Purchases] - DEBUG: ℹ️ Detected active subscriptions changed. Clearing trial or intro eligibility cache.

@DavidKadlcek
Copy link
Author

@NachoSoto any update?

@nathjyo
Copy link

nathjyo commented May 14, 2023

We shipped an update (4.18.0) with a couple of new debug logs to help debug this. Would you mind trying to reproduce it with it and sending us the new logs? 🙏

ironically this same issue only started with me when I updated RC to 4.18.0

@NachoSoto
Copy link
Contributor

What version did you update from?

@AnzhyNetpeak
Copy link

Hello, @NachoSoto
Any update on this issue? It's still present, checked 4.19.1 and 4.20.0

@NachoSoto
Copy link
Contributor

I've dug into your logs and our implementation, and the only explanation to this happening is that something is calling SKPaymentQueue.finishTransaction from outside the SDK. Is there a chance something else in your code could be doing that?

Additionally, when you're testing with .storekit config files, could you open the "Editor" menu and see if you have something configured there that would interrupt purchases? What's your renewal rate?

Screenshot 2023-06-01 at 14 10 34

@NachoSoto NachoSoto added the status: needs-additional-info Issues that are missing steps from bug template label Jun 1, 2023
NachoSoto added a commit that referenced this issue Jun 1, 2023
… calls

Just a small addition that might help debug #2415.
@NachoSoto
Copy link
Contributor

NachoSoto commented Jun 1, 2023

Posting this for reference:
This is what a normal SK1 purchase flow looks like (verified on simulator and device):

INFO: 💰 Purchasing Product 'com.revenuecat.monthly_4.99.1_week_intro'
DEBUG: ℹ️ Adding payment for product 'com.revenuecat.monthly_4.99.1_week_intro'. 6 transactions already in the queue.
DEBUG: ℹ️ StoreKit1Wrapper (0x00000002817e86c0) updatedTransaction: com.revenuecat.monthly_4.99.1_week_intro 0
DEBUG: ℹ️ StoreKit1Wrapper (0x00000002817e86c0) updatedTransaction: com.revenuecat.monthly_4.99.1_week_intro 2000000342560896 2000000336611463 1
DEBUG: ℹ️ PostReceiptDataOperation: Started
DEBUG: ℹ️ PostReceiptDataOperation: Finished
INFO: 💰 Finishing transaction '2000000342560896' for product 'com.revenuecat.monthly_4.99.1_week_intro'
DEBUG: ℹ️ StoreKit1Wrapper (0x00000002817e86c0) removedTransaction: com.revenuecat.monthly_4.99.1_week_intro 2000000342560896 2000000336611463 1
INFO: 😻💰 Purchased product - 'com.revenuecat.monthly_4.99.1_week_intro'

And this is what you're getting:

INFO: 💰 Purchasing Product 'david.kadlcek.GuessWho.annualAccess'
DEBUG: ℹ️ Adding payment for product 'david.kadlcek.GuessWho.annualAccess'. 0 transactions already in the queue.
DEBUG: ℹ️ StoreKit1Wrapper (0x000000028265f780) updatedTransaction: david.kadlcek.GuessWho.annualAccess 0
DEBUG: ℹ️ StoreKit1Wrapper (0x000000028265f780) updatedTransaction: david.kadlcek.GuessWho.annualAccess 2000000323180005 2000000077648060 1
DEBUG: ℹ️ StoreKit1Wrapper (0x000000028265f780) removedTransaction: david.kadlcek.GuessWho.annualAccess 2000000323180005 2000000077648060 1
DEBUG: ℹ️ StoreKit1Wrapper (0x000000028265f780) removedTransaction for david.kadlcek.GuessWho.annualAccess but no callbacks to notify
DEBUG: ℹ️ PostReceiptDataOperation: Started
DEBUG: ℹ️ PostReceiptDataOperation: Finished
INFO: 💰 Finishing transaction '2000000323180005' for product 'david.kadlcek.GuessWho.annualAccess'

When we try to finish the transaction, StoreKit doesn't get back to us because it wasn't there to begin with.
We could handle that case and consider it finished, but we should understand why this is happening.

@Tibbs
Copy link

Tibbs commented Jun 4, 2023

I had the same issue a few months ago when I updated my app. My workaround was to go back to 4.16.0

@DavidKadlcek
Copy link
Author

DavidKadlcek commented Jun 4, 2023

@NachoSoto There is no way, that I call SKPaymentQueue.finishTransaction from the outside of the SDK. Also I didn't do any edit in the "Edit". Btw everything works perfectly earlier. So I assume that there has to be a problem since some version

@NachoSoto
Copy link
Contributor

NachoSoto commented Jun 4, 2023

Ir would be really helpful if you could put a breakpoint on StoreKit1Wrapper.paymentQueue(_:, removedTransactions:) and send us the stack trace when that gets called in the middle of a purchase.
Let me know if you need any help with that.

@emissarman
Copy link

Same issue on last version of sdk. On 4.16.0 works fine.

@NachoSoto
Copy link
Contributor

@emissarman thanks for letting us know.
Unfortunately we're still unable to reproduce locally, but it would be extremely helpful if you could debug this and put a breakpoint on StoreKit1Wrapper.paymentQueue(_:, removedTransactions:) to see why that is being called. Let me know if I can help you do that so we can get to the root of this issue :)

@NachoSoto
Copy link
Contributor

@DavidKadlcek and I just had a call and looked through the issue together. We found out that the root of the problem was https://github.com/bizz84/SwiftyStoreKit and how it was set up. SwiftStoreKit was also calling finishTransaction:.

@Tibbs @emissarman can you let us know if you're also using that framework or other StoreKit packages?

Suggested solutions:

  • Migrate fully to RevenueCat instead of having multiple dependencies handling StoreKit transaction updates. We have a nice guide to help you do that: https://www.revenuecat.com/docs/swiftystorekit
  • Ensure that the other dependencies don't call finishTransactions. Specifically, SwiftyStoreKit suggests calling completeTransactions and inside the closure calling finishTransactions. In order for RevenueCat's SDK to work, you'd have to remove that code and let RevenueCat handle the transactions automatically:
    image

I'll mark this bug as completed, but let us know if you still need help with this.

@NachoSoto NachoSoto removed the status: needs-additional-info Issues that are missing steps from bug template label Jun 6, 2023
@github-actions
Copy link

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

@github-actions github-actions bot locked and limited conversation to collaborators Jun 14, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
Projects
None yet
Development

No branches or pull requests

7 participants