Skip to content

4.17.4 Breaks purchases y and now continue breaking #2364

Closed
Closed
4.17.4 Breaks purchases y and now continue breaking#2364
Labels
bug

Description

@jesus-mg-ios
jesus-mg-ios
opened on Mar 22, 2023

Describe the bug
The purchase process was never finished on the client side, it stalled on getting customer info after purchase. Also, it's reproducible on devices and simulators. If you restart the app, the customer info is got and the purchase is retrieved.

  1. Environment
    1. Platform: iOS
    2. SDK version: 4.17.8
    3. StoreKit 2 (disabled with useStoreKit2IfEnabled(false)) (Y/N): Default
    4. OS version: 16.2
    5. Xcode version: 14.2
    6. How widespread is the issue. Percentage of devices affected.
  2. Debug logs that reproduce the issue -> Below
  3. Steps to reproduce, with a description of expected vs. actual behavior -> Make a simple purchase
  4. Other information (e.g. stacktraces, related issues, suggestions how to fix, links for us to have context, eg. stackoverflow, etc.)

Additional context

2023-03-22 14:26:43.807600+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ Configuring SDK using provided UserDefaults.
2023-03-22 14:26:43.823931+0100 app[50859:3747218] [Purchases] - DEBUG: 👤 Identifying App User ID
2023-03-22 14:26:43.837324+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ Debug logging enabled
2023-03-22 14:26:43.837524+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ SDK Version - 4.17.8
2023-03-22 14:26:43.837684+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ Bundle ID - app.com
2023-03-22 14:26:43.837868+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ System Version - Version 16.2 (Build 20C52)
2023-03-22 14:26:43.837993+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ Using a simulator. Ensure you have a StoreKit Config file set up before trying to fetch products or make purchases.
See https://errors.rev.cat/testing-in-simulator for more details.
2023-03-22 14:26:43.838164+0100 app[50859:3747218] [Purchases] - DEBUG: 👤 Initial App User ID set
2023-03-22 14:26:43.839702+0100 app[50859:3747218] [Purchases] - WARN: 🍎‼️ AdServices attribution token is not available in the simulator
2023-03-22 14:26:43.841261+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ setting values for attributes: ["mediaSource"]
2023-03-22 14:26:43.842431+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ Attribute set locally: [SubscriberAttribute] key: mediaSource value: VALUE setTime: 2023-03-22 13:26:43 +0000. It will be synced to the backend when the app backgrounds/foregrounds or when a purchase is made.
2023-03-22 14:26:43.856956+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ Delegate set
2023-03-22 14:26:53.200792+0100 app[50859:3747218] [APP] purchases delegate <RCPurchases: 0x600000060380>, info <CustomerInfo:
originalApplicationVersion=,
latestExpirationDate=nil,
activeEntitlements=[:],
activeSubscriptions=[:],
nonSubscriptions=[],
requestDate=2023-03-22 13:26:00 +0000,
firstSeen=2023-03-22 13:26:00 +0000,
originalAppUserId=SubscriberUUID,
entitlements=[:]
>
2023-03-22 14:26:53.479862+0100 app[50859:3747535] [Purchases] - DEBUG: ℹ️ PostSubscriberAttributesOperation: Started
2023-03-22 14:26:53.480030+0100 app[50859:3747535] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request POST subscribers/SubscriberUUID/attributes
2023-03-22 14:26:53.490036+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ setting reserved attribute: $email
2023-03-22 14:26:53.499982+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ applicationDidBecomeActive
2023-03-22 14:26:53.502768+0100 app[50859:3747535] [Purchases] - DEBUG: ℹ️ API request started: POST /v1/subscribers/SubscriberUUID/attributes
2023-03-22 14:26:53.578201+0100 app[50859:3747218] [Purchases] - WARN: 🍎‼️ AdServices attribution token is not available in the simulator
2023-03-22 14:26:53.579819+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ Vending CustomerInfo from cache.
2023-03-22 14:26:53.580715+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ Vending CustomerInfo from cache.
2023-03-22 14:26:53.595808+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ Offerings cache is stale, updating caches
2023-03-22 14:26:53.596644+0100 app[50859:3747535] [Purchases] - DEBUG: ℹ️ Network operation 'GetOfferingsOperation' found with the same cache key 'GetOfferingsOpe...'. Skipping request.
2023-03-22 14:26:54.412896+0100 app[50859:3747542] [Purchases] - DEBUG: ℹ️ API request completed: POST /v1/subscribers/SubscriberUUID/attributes (200)
2023-03-22 14:26:54.413733+0100 app[50859:3747542] [Purchases] - INFO: ℹ️ Marking attributes as synced for App User ID: SubscriberUUID:
 attributes: ["mediaSource": [SubscriberAttribute] key: mediaSource value: VALUE setTime: 2023-03-22 13:26:43 +0000]
2023-03-22 14:26:54.413888+0100 app[50859:3747542] [Purchases] - DEBUG: ℹ️ Found 1 unsynced attributes for App User ID: SubscriberUUID
2023-03-22 14:26:54.414051+0100 app[50859:3747542] [Purchases] - DEBUG: ℹ️ Unsynced attributes: ["mediaSource": [SubscriberAttribute] key: mediaSource value: VALUE setTime: 2023-03-22 13:26:43 +0000]
2023-03-22 14:26:54.415110+0100 app[50859:3747542] [Purchases] - DEBUG: 😻 Subscriber attributes synced successfully for App User ID: SubscriberUUID
2023-03-22 14:26:54.415210+0100 app[50859:3747542] [Purchases] - WARN: ⚠️ The appUserID passed to logIn is the same as the one already cached. No action will be taken.
2023-03-22 14:26:54.415685+0100 app[50859:3747542] [Purchases] - DEBUG: ℹ️ Vending CustomerInfo from cache.
2023-03-22 14:26:54.415764+0100 app[50859:3747542] [Purchases] - DEBUG: ℹ️ PostSubscriberAttributesOperation: Finished
2023-03-22 14:26:54.415918+0100 app[50859:3747542] [Purchases] - DEBUG: ℹ️ Serial request done: POST subscribers/SubscriberUUID/attributes, 0 requests left in the queue
2023-03-22 14:26:54.415940+0100 app[50859:3747543] [Purchases] - DEBUG: ℹ️ GetCustomerInfoOperation: Started
2023-03-22 14:26:54.418490+0100 app[50859:3747543] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request GET subscribers/SubscriberUUID
2023-03-22 14:26:54.418781+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ Vending CustomerInfo from cache.
2023-03-22 14:26:54.419210+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ Vending CustomerInfo from cache.
2023-03-22 14:26:54.419403+0100 app[50859:3747543] [Purchases] - DEBUG: ℹ️ API request started: GET /v1/subscribers/SubscriberUUID
2023-03-22 14:26:54.420839+0100 app[50859:3747543] [Purchases] - DEBUG: ℹ️ Network operation 'GetOfferingsOperation' found with the same cache key 'GetOfferingsOpe...'. Skipping request.
2023-03-22 14:26:54.533759+0100 app[50859:3747542] [Purchases] - DEBUG: ℹ️ API request completed: GET /v1/subscribers/SubscriberUUID (200)
2023-03-22 14:26:54.539876+0100 app[50859:3747542] [Purchases] - DEBUG: ℹ️ Sending latest CustomerInfo to delegate.
2023-03-22 14:26:54.540094+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ Detected active subscriptions changed. Clearing trial or intro eligibility cache.
2023-03-22 14:26:54.540135+0100 app[50859:3747542] [Purchases] - DEBUG: 😻 CustomerInfo updated from network.
2023-03-22 14:26:54.540292+0100 app[50859:3747218] [APP] purchases delegate <RCPurchases: 0x600000060380>, info <CustomerInfo:
originalApplicationVersion=,
latestExpirationDate=nil,
activeEntitlements=[:],
activeSubscriptions=[:],
nonSubscriptions=[],
requestDate=2023-03-22 13:26:54 +0000,
firstSeen=2023-03-22 13:26:00 +0000,
originalAppUserId=SubscriberUUID,
entitlements=[:]
>
2023-03-22 14:26:54.540372+0100 app[50859:3747542] [Purchases] - DEBUG: ℹ️ GetCustomerInfoOperation: Finished
2023-03-22 14:26:54.540737+0100 app[50859:3747534] [Purchases] - DEBUG: ℹ️ GetOfferingsOperation: Started
2023-03-22 14:26:54.540730+0100 app[50859:3747542] [Purchases] - DEBUG: ℹ️ Serial request done: GET subscribers/SubscriberUUID, 0 requests left in the queue
2023-03-22 14:26:54.540924+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ Vending CustomerInfo from cache.
2023-03-22 14:26:54.540994+0100 app[50859:3747534] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request GET subscribers/SubscriberUUID/offerings
2023-03-22 14:26:54.541333+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ Vending CustomerInfo from cache.
2023-03-22 14:26:54.542524+0100 app[50859:3747534] [Purchases] - DEBUG: ℹ️ API request started: GET /v1/subscribers/SubscriberUUID/offerings
2023-03-22 14:26:54.657396+0100 app[50859:3747542] [Purchases] - DEBUG: ℹ️ API request completed: GET /v1/subscribers/SubscriberUUID/offerings (200)
2023-03-22 14:26:54.663233+0100 app[50859:3747542] [Purchases] - DEBUG: ℹ️ No existing products cached, starting store products request for: ["product1", "product2", "product3", "product4"]
2023-03-22 14:26:54.663459+0100 app[50859:3747542] [Purchases] - DEBUG: ℹ️ Found an existing request for products: ["product2", "product1", "product4", "product3"], appending to completion
2023-03-22 14:26:54.663564+0100 app[50859:3747536] [Purchases] - DEBUG: ℹ️ No existing products cached, starting store products request for: ["product1", "product2", "product3", "product4"]
2023-03-22 14:26:54.663695+0100 app[50859:3747542] [Purchases] - DEBUG: ℹ️ Found an existing request for products: ["product3", "product2", "product1", "product4"], appending to completion
2023-03-22 14:26:54.663829+0100 app[50859:3747542] [Purchases] - DEBUG: ℹ️ GetOfferingsOperation: Finished
2023-03-22 14:26:54.664035+0100 app[50859:3747542] [Purchases] - DEBUG: ℹ️ Serial request done: GET subscribers/SubscriberUUID/offerings, 0 requests left in the queue
2023-03-22 14:26:54.664061+0100 app[50859:3747543] [Purchases] - DEBUG: ℹ️ PostSubscriberAttributesOperation: Started
2023-03-22 14:26:54.664389+0100 app[50859:3747543] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request POST subscribers/SubscriberUUID/attributes
2023-03-22 14:26:54.665289+0100 app[50859:3747543] [Purchases] - DEBUG: ℹ️ API request started: POST /v1/subscribers/SubscriberUUID/attributes
2023-03-22 14:26:54.696117+0100 app[50859:3747543] [Purchases] - DEBUG: 😻 Store products request received response
2023-03-22 14:26:54.696084+0100 app[50859:3747542] [Purchases] - DEBUG: 😻 Store products request finished
2023-03-22 14:26:54.930348+0100 app[50859:3747536] [Purchases] - DEBUG: ℹ️ API request completed: POST /v1/subscribers/SubscriberUUID/attributes (200)
2023-03-22 14:26:54.930519+0100 app[50859:3747536] [Purchases] - INFO: ℹ️ Marking attributes as synced for App User ID: SubscriberUUID:
 attributes: ["mediaSource": [SubscriberAttribute] key: mediaSource value: VALUE setTime: 2023-03-22 13:26:43 +0000]
2023-03-22 14:26:54.930713+0100 app[50859:3747536] [Purchases] - DEBUG: ℹ️ Found 0 unsynced attributes for App User ID: SubscriberUUID
2023-03-22 14:26:54.930810+0100 app[50859:3747536] [Purchases] - DEBUG: 😻 Subscriber attributes synced successfully for App User ID: SubscriberUUID
2023-03-22 14:26:54.930913+0100 app[50859:3747536] [Purchases] - DEBUG: ℹ️ PostSubscriberAttributesOperation: Finished
2023-03-22 14:26:54.931031+0100 app[50859:3747536] [Purchases] - DEBUG: ℹ️ Serial request done: POST subscribers/SubscriberUUID/attributes, 0 requests left in the queue
2023-03-22 14:26:59.892206+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ Vending Offerings from cache

---------- USER TAPS ON PURCHASE BUTTON --------

2023-03-22 14:27:10.030622+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ Skipping products request for these products because they were already cached: ["product4"]
2023-03-22 14:27:10.030860+0100 app[50859:3747218] [Purchases] - INFO: 💰 Purchasing Product 'product4'
2023-03-22 14:27:10.035119+0100 app[50859:3747543] [Purchases] - DEBUG: ℹ️ StoreKit1Wrapper (0x0000600001d662e0) updatedTransaction: product4 0
2023-03-22 14:27:17.705403+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ applicationDidBecomeActive
2023-03-22 14:27:17.705574+0100 app[50859:3747218] [Purchases] - WARN: 🍎‼️ AdServices attribution token is not available in the simulator
2023-03-22 14:28:06.141235+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ Vending CustomerInfo from cache.
2023-03-22 14:28:12.483234+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ Vending CustomerInfo from cache.
2023-03-22 14:28:25.345168+0100 app[50859:3748844] [Purchases] - DEBUG: ℹ️ StoreKit1Wrapper (0x0000600001d662e0) updatedTransaction: product4 0 1
2023-03-22 14:28:25.351774+0100 app[50859:3748844] [Purchases] - DEBUG: ℹ️ Force refreshing the receipt to get latest transactions from Apple.
2023-03-22 14:28:25.351919+0100 app[50859:3748844] [Purchases] - DEBUG: ℹ️ SKReceiptRefreshRequest started
2023-03-22 14:28:25.387149+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ SKReceiptRefreshRequest finished
2023-03-22 14:28:25.393774+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ Loaded receipt from url CoreSimulator/Devices/9834F27A-484C-468E-BF70-5D1F926E2CF5/data/Containers/Data/Application/7BB899C3-C24E-4F19-8DAE-FA4B6AC59423/StoreKit/receipt
2023-03-22 14:28:25.393945+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ Skipping products request for these products because they were already cached: ["product4"]
2023-03-22 14:28:25.394700+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ Found 0 unsynced attributes for App User ID: SubscriberUUID
2023-03-22 14:28:25.406205+0100 app[50859:3749816] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Started
2023-03-22 14:28:25.406607+0100 app[50859:3749816] [Purchases] - INFO: ℹ️ Parsing receipt
2023-03-22 14:28:25.408174+0100 app[50859:3749816] [Purchases] - INFO: ℹ️ Receipt parsed successfully
2023-03-22 14:28:25.409551+0100 app[50859:3749816] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Posting receipt (note: the contents might not be up-to-date, but it will be refreshed with Apple's servers):
{
  "opaque_value" : "1X+T\/wwAAAA=",
  "sha1_hash" : "gyFsW6obz08OJZNrAN1JU5tUGuE=",
  "bundle_id" : "app.com",
  "in_app_purchases" : [
    {
      "product_id" : "product4",
      "quantity" : 1,
      "transaction_id" : "0",
      "is_in_intro_offer_period" : true,
      "expires_date" : "2023-03-29T13:27:17Z",
      "purchase_date" : "2023-03-22T13:27:17Z",
      "product_type" : -1
    }
  ],
  "application_version" : "014db39a",
  "creation_date" : "2023-03-22T13:28:25Z",
  "expiration_date" : "4001-01-01T00:00:00Z"
}
2023-03-22 14:28:25.409708+0100 app[50859:3749816] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request POST receipts
2023-03-22 14:28:25.412220+0100 app[50859:3749816] [Purchases] - DEBUG: ℹ️ API request started: POST /v1/receipts
2023-03-22 14:28:25.534621+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ applicationDidBecomeActive
2023-03-22 14:28:25.534793+0100 app[50859:3747218] [Purchases] - WARN: 🍎‼️ AdServices attribution token is not available in the simulator
2023-03-22 14:28:25.535259+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ Vending CustomerInfo from cache.
2023-03-22 14:28:25.535589+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ Vending CustomerInfo from cache.
2023-03-22 14:28:26.331996+0100 app[50859:3749816] [Purchases] - DEBUG: ℹ️ API request completed: POST /v1/receipts (200)
2023-03-22 14:28:26.339331+0100 app[50859:3749816] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Finished
2023-03-22 14:28:26.339635+0100 app[50859:3749816] [Purchases] - DEBUG: ℹ️ Serial request done: POST receipts, 0 requests left in the queue
2023-03-22 14:28:26.346153+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ Sending updated CustomerInfo to delegate.
2023-03-22 14:28:26.346358+0100 app[50859:3747218] [Purchases] - DEBUG: ℹ️ Detected active subscriptions changed. Clearing trial or intro eligibility cache.
2023-03-22 14:28:26.351064+0100 app[50859:3747218] [APP] purchases delegate <RCPurchases: 0x600000060380>, info <CustomerInfo:
originalApplicationVersion=1.0,
latestExpirationDate=Optional(2023-03-29 13:27:17 +0000),
activeEntitlements=["all access": "<EntitlementInfo: \"\nidentifier=all access,\nisActive=true,\nwillRenew=true,\nperiodType=PeriodType(rawValue: 1),\nlatestPurchaseDate=Optional(2023-03-22 13:27:17 +0000),\noriginalPurchaseDate=Optional(2023-03-22 13:27:17 +0000),\nexpirationDate=Optional(2023-03-29 13:27:17 +0000),\nstore=Store(rawValue: 0),\nproductIdentifier=product4,\nisSandbox=true,\nunsubscribeDetectedAt=nil,\nbillingIssueDetectedAt=nil,\nownershipType=PurchaseOwnershipType(rawValue: 0)\n>"],
activeSubscriptions=["product4": "expiresDate: Optional(2023-03-29 13:27:17 +0000)"],
nonSubscriptions=[],
requestDate=2023-03-22 13:28:26 +0000,
firstSeen=2023-03-22 13:26:00 +0000,
originalAppUserId=SubscriberUUID,
entitlements=["all access": "<EntitlementInfo: \"\nidentifier=all access,\nisActive=true,\nwillRenew=true,\nperiodType=PeriodType(rawValue: 1),\nlatestPurchaseDate=Optional(2023-03-22 13:27:17 +0000),\noriginalPurchaseDate=Optional(2023-03-22 13:27:17 +0000),\nexpirationDate=Optional(2023-03-29 13:27:17 +0000),\nstore=Store(rawValue: 0),\nproductIdentifier=product4,\nisSandbox=true,\nunsubscribeDetectedAt=nil,\nbillingIssueDetectedAt=nil,\nownershipType=PurchaseOwnershipType(rawValue: 0)\n>"]
>

The app waited for a purchase, the purchase was made, (I think), and then trying to getting the customer info it doesn't end.
Appears the environment alert, and then never finishes.

I think it's related to the only change in customerInfo made on 4.17.4. It seems to hang also de UI ... In 4.17.3 the same code works as expected. I tested it on 4.17.8.

Thanks in advance.

image

image

Metadata

Metadata

Assignees

No one assigned

    Labels

    bug

    Type

    No type

    Fields

    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