search

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.22k stars 295 forks source link

Bug purchasing product #4020

Open jesus-mg-ios opened 1 week ago

jesus-mg-ios commented 1 week ago

Describe the bug

Users on a non-production environment (we don't know if it's happening in production) enter the paywall and then push the button to pay. Without showing the purchase sheet, RevenueCat says, "Oh, it's purchased." Then, the next screen appears. However, 2 or 3 seconds later, RevenueCat updates the status and says, "Hey, there's no subscription." If the user goes to pay again, the Apple sheet appears, prompting the user to enter the sandbox account credentials to complete the subscription payment.

  1. Environment
    1. Platform: iOS
    2. SDK version: 4.41.2
    3. StoreKit version:
      • [x] StoreKit 1
      • [ ] StoreKit 2 (enabled with usesStoreKit2IfAvailable(true))
    4. OS version:
    5. Xcode version:
    6. Device and/or simulator:
      • [X] Device
      • [ ] Simulator
    7. Environment:
      • [X] Sandbox
      • [ ] TestFight
      • [ ] Production ?
    8. How widespread is the issue. Percentage of devices affected.
  2. Debug logs that reproduce the issue. Complete logs with Purchases.logLevel = .verbose will help us debug this issue.
INFO: ℹ️ Marking AdServices attribution token as synced for App User ID: USERID
Updating selectors after delegate addition failed with: Error Domain=NSCocoaErrorDomain Code=4099 
"The connection to service with pid 94 named com.apple.commcenter.coretelephony.xpc was invalidated from this process." 
UserInfo={NSDebugDescription=The connection to service with pid 94 named com.apple.commcenter.coretelephony.xpc was invalidated from this process.}
WARN: ⚠️ The appUserID passed to logIn is the same as the one already cached. No action will be taken.

attributes: ["$email": [SubscriberAttribute] key: $email value: email@email.com setTime: 2024-07-04 1:25:44 PM +0000]
INFO: ℹ️ Marking attributes as synced for App User ID: USERID:
attributes: ["$email": [SubscriberAttribute] key: $email value: email@email.com setTime: 2024-07-04 1:25:44 PM +0000]
WARN: ⚠️ The appUserID passed to logIn is the same as the one already cached. No action will be taken.

INFO: 💰 Finishing transaction '2000000645085987' for product 'app_product'
INFO: ℹ️ Marking attributes as synced for App User ID: USERID:
attributes: ["$email": [SubscriberAttribute] key: $email value: email@email.com setTime: 2024-07-04 1:25:44 PM +0000]

purchases delegate <RCPurchases: 0x10ce19050>, info <CustomerInfo:
originalApplicationVersion=1.0,
latestExpirationDate=Optional(2024-07-02 8:33:43 PM +0000),
activeEntitlements=[:],
activeSubscriptions=[:],
nonSubscriptions=[],
requestDate=2024-07-04 12:59:38 PM +0000,
firstSeen=2024-03-14 9:33:58 AM +0000,
originalAppUserId=$RCAnonymousID:f463ce6a0f994aa8be0090b42976aef8,
entitlements=["entitlement1": "<EntitlementInfo: \"\nidentifier=entitlement1,\nisActive=false,\nwillRenew=false,\nperiodType=PeriodType(rawValue: 0),\nlatestPurchaseDate=Optional(2024-06-06 9:40:33 AM +0000),\noriginalPurchaseDate=Optional(2024-03-14 9:40:33 AM +0000),\nexpirationDate=Optional(2024-06-12 9:44:08 AM +0000),\nstore=Store(rawValue: 3),\nproductIdentifier=prod_LCWjS9AccWbDa8,\nproductPlanIdentifier=null,\nisSandbox=true,\nunsubscribeDetectedAt=Optional(2024-06-12 9:44:08 AM +0000),\nbillingIssueDetectedAt=Optional(2024-06-06 9:42:12 AM +0000),\nownershipType=PurchaseOwnershipType(rawValue: 0),\nverification=VerificationResult.notRequested\n>", 
"entitlement2s": "<EntitlementInfo: \"\nidentifier=entitlement2s,\nisActive=false,\nwillRenew=false,\nperiodType=PeriodType(rawValue: 0),\nlatestPurchaseDate=Optional(2024-07-02 7:33:43 PM +0000),\noriginalPurchaseDate=Optional(2024-03-14 9:36:15 AM +0000),\nexpirationDate=Optional(2024-07-02 8:33:43 PM +0000),\nstore=Store(rawValue: 0),\nproductIdentifier=app_product,\nproductPlanIdentifier=null,\nisSandbox=true,\nunsubscribeDetectedAt=Optional(2024-07-02 7:37:14 PM +0000),\nbillingIssueDetectedAt=nil,\nownershipType=PurchaseOwnershipType(rawValue: 0),\nverification=VerificationResult.notRequested\n>"]
verification=VerificationResult.notRequested
>

ERROR: 😿‼️ One or more of the attributes sent could not be saved. ["$thirdId": "thirdId ID cannot be modified.", "$idfv": "IDFV cannot be modified."]
INFO: 💰 Finishing transaction '2000000645121224' for product 'app_product'
INFO: ℹ️ Marking attributes as synced for App User ID: USERID:
attributes: ["$email": [SubscriberAttribute] key: $email value: email@email.com setTime: 2024-07-04 1:25:44 PM +0000, "$thirdId": [SubscriberAttribute] key: $thirdId value: 1720099217062-3763104 setTime: 2024-07-04 1:25:46 PM +0000, "$idfa": [SubscriberAttribute] key: $idfa value: setTime: 2024-07-04 1:25:46 PM +0000, "$idfv": [SubscriberAttribute] key: $idfv value: IDFAVALUE setTime: 2024-07-04 1:25:46 PM +0000, "$ip": [SubscriberAttribute] key: $ip value: true setTime: 2024-07-04 1:25:46 PM +0000]

ERROR: 😿‼️ One or more of the attributes sent could not be saved. ["$idfv": "IDFV cannot be modified.", "$thirdId": "thirdId ID cannot be modified."]
INFO: 💰 Finishing transaction '2000000645149212' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645202848' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645178101' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645149211' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645121223' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645085986' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645202848' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645178101' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645149211' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645121223' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645085986' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645202848' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645178101' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645149211' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645121223' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645085986' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645202848' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645178101' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645149211' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645121223' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645085986' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645202848' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645178101' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645149211' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645121223' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645085986' for product 'app_product'
ERROR: 😿‼️ One or more of the attributes sent could not be saved. ["$thirdId": "thirdId ID cannot be modified.", "$idfv": "IDFV cannot be modified."]
INFO: 💰 Finishing transaction '2000000645178101' for product 'app_product'
INFO: ℹ️ Marking attributes as synced for App User ID: USERID:
attributes: ["$idfv": [SubscriberAttribute] key: $idfv value: IDFAVALUE setTime: 2024-07-04 1:25:46 PM +0000, "$email": [SubscriberAttribute] key: $email value: email@email.com setTime: 2024-07-04 1:25:44 PM +0000, "$thirdId": [SubscriberAttribute] key: $thirdId value: 1720099217062-3763104 setTime: 2024-07-04 1:25:46 PM +0000, "$idfa": [SubscriberAttribute] key: $idfa value: setTime: 2024-07-04 1:25:46 PM +0000, "$ip": [SubscriberAttribute] key: $ip value: true setTime: 2024-07-04 1:25:46 PM +0000]

ERROR: 😿‼️ One or more of the attributes sent could not be saved. ["$idfv": "IDFV cannot be modified.", "$thirdId": "thirdId ID cannot be modified."]
INFO: 💰 Finishing transaction '2000000645202849' for product 'app_product'
Tapped Buy
INFO: 💰 Purchasing Product 'app_product'
INFO: ℹ️ Marking attributes as synced for App User ID: USERID:
attributes: ["$thirdId": [SubscriberAttribute] key: $thirdId value: 1720099217062-3763104 setTime: 2024-07-04 1:25:46 PM +0000, "$ip": [SubscriberAttribute] key: $ip value: true setTime: 2024-07-04 1:25:46 PM +0000, "$idfa": [SubscriberAttribute] key: $idfa value: setTime: 2024-07-04 1:25:46 PM +0000, "$email": [SubscriberAttribute] key: $email value: email@email.com setTime: 2024-07-04 1:25:44 PM +0000, "$idfv": [SubscriberAttribute] key: $idfv value: IDFAVALUE setTime: 2024-07-04 1:25:46 PM +0000]

INFO: 😻💰 Purchased product - 'app_product'
Purchased ----> true  ----> public typealias PurchaseCompletedBlock = @MainActor @Sendable (RevenueCat.StoreTransaction?, RevenueCat.CustomerInfo?, RevenueCat.PublicError?, Bool) -> Void -> RevenueCat.PublicError is nil, Bool is false (User has no cancelled)

INFO: 💰 Finishing transaction '2000000645202848' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645178101' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645085986' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645121223' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645149211' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645202848' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645178101' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645085986' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645149211' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645202848' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645178101' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645149211' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645085986' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645121223' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645121223' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645149212' for product 'app_product'
INFO: 💰 Finishing transaction '2000000645202849' for product 'app_product'
ERROR: 😿‼️ The receipt is not valid. The purchased product was missing in the receipt. This is typically due to a bug in StoreKit.
WARN: ⚠️ Attempt to update CustomerInfo from network failed. The operation couldn’t be completed. (RevenueCat.BackendError error 0.)
Underlying error: The receipt is not valid. The purchased product was missing in the receipt. This is typically due to a bug in StoreKit.
ERROR: 😿‼️ The receipt is not valid. The purchased product was missing in the receipt. This is typically due to a bug in StoreKit.
ERROR: 😿‼️ The receipt is not valid. The purchased product was missing in the receipt. This is typically due to a bug in StoreKit.
WARN: ⚠️ Attempt to update CustomerInfo from network failed. The operation couldn’t be completed. (RevenueCat.BackendError error 0.)
Underlying error: The receipt is not valid. The purchased product was missing in the receipt. This is typically due to a bug in StoreKit.
ERROR: 😿‼️ The receipt is not valid. The purchased product was missing in the receipt. This is typically due to a bug in StoreKit.
WARNING: sendOnFocusCallWithParams unattributed failed, will retry on next open

Purchase delegate -> No subscription....

  1. Steps to reproduce, with a description of expected vs. actual behavior

  2. Other information (e.g. stacktraces, related issues, suggestions how to fix, links for us to have context, eg. stackoverflow, etc.)

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

RCGitBot commented 1 week ago

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

aboedo commented 1 week ago

Hey @jesus-mg-ios, off the top of my head I imagine what might be happening is that you have the time rate for accelerated subscriptions set to a very fast value (like a renewal every 2 seconds), and that it being set to that fast a renewal rate just means that we get throttled by Apple APIs and can't get a new receipt in time, leading to the issues.

This is based off of the fact that you also have a lot of transactions getting finished at the same time in the logs.

image

Setting that to a lower value, like a renewal every 5 mins, you shouldn't be able to reproduce. And in production, that should never happen, of course, since renewals take days / weeks / months / years instead of seconds. Even in TestFlight / regular Sandbox they last a few mins.

Let me know if that's not the case!

jesus-mg-ios commented 1 week ago
image

Also I'm not using the storekit file on the scheme, so anyways it shoudn't doesnt care about this option.

aboedo commented 1 week ago

@jesus-mg-ios ohh interesting, thanks for getting back to me. In that case I think it might have more to do with the amount of transactions in your sandbox account, seems like there's a lot to process right off the bat and sandbox can misbehave.

Does this happen to you if you use a different sandbox account?

jesus-mg-ios commented 6 days ago

I've cleared the user's data, and after making 4-5 purchases, the issue appears (which could happen in production). It might be worth examining the code that manages transactions.

It seems related to an inconsistent internal cache, state or data race, because it’s unlikely that RevenueCat would initially indicate a purchase without showing the Apple purchase sheet, only to correct itself 2-3 seconds later. @aboedo