Solved

iOS SDK - Purchases.shared.offerings completion block never called

  • 21 September 2021
  • 7 replies
  • 334 views
D
Badge +1

Hi mates!

I working all day, and all fine with this fetching method. But right now I have a problem when call Purchases.shared.offerings - completion block NEVER called. In console log, I see that request message only, and nothing happens after that:

[Purchases] - DEBUG: ℹ️ Requesting products from the store with identifiers: {(

    "standard.6months",

    "standard.1month",

    "advanced.1month",

    "standard.1year",

    "advanced.1year",

    "advanced.6months"

)}

I tried remove app bundle, restart macOS, restart iOS, but without any success. This problem happen only when I running app on device. When I set Xcode StoreKit.configuration for target - this method works as expected. Please help me solve the problem.

Running on iPhone Xr on iOS 15

icon

Best answer by Andy 19 October 2021, 19:52

View original

7 replies

jazmine
Rank
Userlevel 3
Badge +7

Hey @Dmitry ,

Could you send debug logs that reproduce this? You can enable debug logs by following this guide. After they're enabled you'll see logs like this in the console:
 

[Purchases] - DEBUG: No cached entitlements, fetching
[Purchases] - DEBUG: GET /v1/subscribers/<APP_USER_ID> 200
[Purchases] - DEBUG: Purchaser info updated, sending to delegate


Please ensure the debug logs include the entire app life-cycle, including the messages printed during initialization of the SDK. The more information you include here, the better we'll be able to help.

 

Let me know if you have any questions!

D
Badge +1

Hello Jazmine,

complete logs here (I changed app name for private reasons).

Loggins from three sessions: 

1. Device without StoreKit.configuration

2. Device without StoreKit.configuration (offerings called with 3 seconds delay, after purchaserInfo call)

3. Simulator with StoreKit.configuration

 

1. Device without StoreKit.configuration

2021-09-22 10:51:09.543838+0300 MyApplication[1223:211830] [Purchases] - DEBUG: ℹ️ Debug logging enabled

2021-09-22 10:51:09.543895+0300 MyApplication[1223:211830] [Purchases] - DEBUG: ℹ️ SDK Version - 3.12.3

2021-09-22 10:51:09.543926+0300 MyApplication[1223:211830] [Purchases] - DEBUG: 👤 Initial App User ID - (null)

2021-09-22 10:51:09.544257+0300 MyApplication[1223:211830] [Purchases] - DEBUG: 👤 Identifying App User ID: $RCAnonymousID:b4bce757716f4bf49aa041b2ab4acfb8

2021-09-22 10:51:09.545365+0300 MyApplication[1223:211830] [Purchases] - DEBUG: ℹ️ Delegate set

2021-09-22 10:51:09.545901+0300 MyApplication[1223:211830] [Purchases] - DEBUG: ℹ️ No cached Offerings, fetching from network

2021-09-22 10:51:10.296298+0300 MyApplication[1223:211830] [Purchases] - DEBUG: ℹ️ PurchaserInfo cache is stale, updating from network in foreground.

2021-09-22 10:51:10.296938+0300 MyApplication[1223:211830] [Purchases] - DEBUG: 😻 PurchaserInfo updated from network.

2021-09-22 10:51:10.305355+0300 MyApplication[1223:212056] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request GET /subscribers/$RCAnonymousID0X0P+0b4bce757716f4bf49aa041b2ab4acfb8

2021-09-22 10:51:10.305764+0300 MyApplication[1223:212056] [Purchases] - DEBUG: ℹ️ API request started: GET /v1/subscribers/$RCAnonymousID:b4bce757716f4bf49aa041b2ab4acfb8

2021-09-22 10:51:10.308736+0300 MyApplication[1223:211830] [Purchases] - DEBUG: ℹ️ applicationDidBecomeActive

2021-09-22 10:51:10.308861+0300 MyApplication[1223:212056] [Purchases] - DEBUG: ℹ️ API request started: GET /v1/subscribers/$RCAnonymousID:b4bce757716f4bf49aa041b2ab4acfb8/offerings

2021-09-22 10:51:10.309374+0300 MyApplication[1223:211830] [Purchases] - DEBUG: ℹ️ PurchaserInfo cache is stale, updating from network in foreground.

2021-09-22 10:51:10.309784+0300 MyApplication[1223:211830] [Purchases] - DEBUG: 😻 PurchaserInfo updated from network.

2021-09-22 10:51:11.153081+0300 MyApplication[1223:212052] [Purchases] - DEBUG: ℹ️ API request completed with status: GET /v1/subscribers/$RCAnonymousID:b4bce757716f4bf49aa041b2ab4acfb8/offerings 200

2021-09-22 10:51:11.155897+0300 MyApplication[1223:212052] [Purchases] - DEBUG: ℹ️ Requesting products from the store with identifiers: {(

    "plan.standard.6months",

    "plan.standard.1month",

    "plan.advanced.1month",

    "plan.standard.1year",

    "plan.advanced.1year",

    "plan.advanced.6months"

)}

2021-09-22 10:51:11.156244+0300 MyApplication[1223:212052] [Purchases] - DEBUG: ℹ️ API request completed with status: GET /v1/subscribers/$RCAnonymousID:b4bce757716f4bf49aa041b2ab4acfb8 201

2021-09-22 10:51:11.159228+0300 MyApplication[1223:212052] [Purchases] - DEBUG: ℹ️ Sending latest PurchaserInfo to delegate.

[:]

2021-09-22 10:51:11.161288+0300 MyApplication[1223:212052] [Purchases] - DEBUG: ℹ️ Serial request done: GET /subscribers/$RCAnonymousID0X0P+0b4bce757716f4bf49aa041b2ab4acfb8, 0 requests left in the queue

 

2. Device without StoreKit.configuration (offerings called with 3 seconds delay, after purchaserInfo call)

App start I called ‘purchaserInfo’, and after 3 seconds I call ‘offerings’ method with asyncAfter):

2021-09-22 11:00:14.943739+0300 MyApplication[1266:217694] [Purchases] - DEBUG: ℹ️ Debug logging enabled

2021-09-22 11:00:14.943808+0300 MyApplication[1266:217694] [Purchases] - DEBUG: ℹ️ SDK Version - 3.12.3

2021-09-22 11:00:14.943841+0300 MyApplication[1266:217694] [Purchases] - DEBUG: 👤 Initial App User ID - (null)

2021-09-22 11:00:14.945795+0300 MyApplication[1266:217694] [Purchases] - DEBUG: ℹ️ Sending latest PurchaserInfo to delegate.

2021-09-22 11:00:14.945941+0300 MyApplication[1266:217694] [Purchases] - DEBUG: ℹ️ Delegate set

2021-09-22 11:00:14.946491+0300 MyApplication[1266:217694] [Purchases] - DEBUG: ℹ️ Vending PurchaserInfo from cache.

[:]

2021-09-22 11:00:15.418394+0300 MyApplication[1266:217694] [Purchases] - DEBUG: ℹ️ applicationDidBecomeActive

2021-09-22 11:00:15.425297+0300 MyApplication[1266:217923] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request GET /subscribers/$RCAnonymousID0X0P+0b4bce757716f4bf49aa041b2ab4acfb8

2021-09-22 11:00:15.425380+0300 MyApplication[1266:217923] [Purchases] - DEBUG: ℹ️ API request started: GET /v1/subscribers/$RCAnonymousID:b4bce757716f4bf49aa041b2ab4acfb8

2021-09-22 11:00:15.426290+0300 MyApplication[1266:217923] [Purchases] - DEBUG: ℹ️ API request started: GET /v1/subscribers/$RCAnonymousID:b4bce757716f4bf49aa041b2ab4acfb8/offerings

2021-09-22 11:00:16.240433+0300 MyApplication[1266:217928] [Purchases] - DEBUG: ℹ️ API request completed with status: GET /v1/subscribers/$RCAnonymousID:b4bce757716f4bf49aa041b2ab4acfb8 304

2021-09-22 11:00:16.243452+0300 MyApplication[1266:217928] [Purchases] - DEBUG: ℹ️ Serial request done: GET /subscribers/$RCAnonymousID0X0P+0b4bce757716f4bf49aa041b2ab4acfb8, 0 requests left in the queue

2021-09-22 11:00:16.243855+0300 MyApplication[1266:217928] [Purchases] - DEBUG: ℹ️ API request completed with status: GET /v1/subscribers/$RCAnonymousID:b4bce757716f4bf49aa041b2ab4acfb8/offerings 304

2021-09-22 11:00:16.244107+0300 MyApplication[1266:217928] [Purchases] - DEBUG: ℹ️ Requesting products from the store with identifiers: {(

    "plan.standard.6months",

    "plan.standard.1month",

    "plan.advanced.1month",

    "plan.standard.1year",

    "plan.advanced.1year",

    "plan.advanced.6months"

)}

2021-09-22 11:00:18.206205+0300 MyApplication[1266:217694] [Purchases] - DEBUG: ℹ️ No cached Offerings, fetching from network

2021-09-22 11:00:18.210244+0300 MyApplication[1266:217934] [Purchases] - DEBUG: ℹ️ API request started: GET /v1/subscribers/$RCAnonymousID:b4bce757716f4bf49aa041b2ab4acfb8/offerings

2021-09-22 11:00:18.385131+0300 MyApplication[1266:217934] [Purchases] - DEBUG: ℹ️ API request completed with status: GET /v1/subscribers/$RCAnonymousID:b4bce757716f4bf49aa041b2ab4acfb8/offerings 304

2021-09-22 11:00:51.249818+0300 MyApplication[1266:217694] [BackgroundTask] Background Task 5 ("SKProductsRequest"), was created over 30 seconds ago. In applications running in the background, this creates a risk of termination. Remember to call UIApplication.endBackgroundTask(_:) for your task in a timely manner to avoid this.

 

3. Simulator with StoreKit.configuration (only this option is working)

Third session (and only this working) running only on Simulator with StoreKit.configuration selected for target:

2021-09-22 11:37:56.292155+0300 MyApplication[18699:162713] [Purchases] - DEBUG: ℹ️ Debug logging enabled

2021-09-22 11:37:56.292280+0300 MyApplication[18699:162713] [Purchases] - DEBUG: ℹ️ SDK Version - 3.12.3

2021-09-22 11:37:56.292407+0300 MyApplication[18699:162713] [Purchases] - DEBUG: 👤 Initial App User ID - (null)

2021-09-22 11:37:56.295825+0300 MyApplication[18699:162713] [Purchases] - DEBUG: ℹ️ Sending latest PurchaserInfo to delegate.

2021-09-22 11:37:56.296162+0300 MyApplication[18699:162713] [Purchases] - DEBUG: ℹ️ Delegate set

2021-09-22 11:37:56.297418+0300 MyApplication[18699:162713] [Purchases] - DEBUG: ℹ️ Vending PurchaserInfo from cache.

["Advanced": <RCEntitlementInfo: identifier=Advanced,

isActive=0,

willRenew=1,

periodType=0,

latestPurchaseDate=2021-09-21 12:46:40 +0000,

originalPurchaseDate=2021-09-21 08:11:56 +0000,

expirationDate=2021-09-21 12:47:10 +0000,

store=0,

productIdentifier=plan.advanced.1month,

isSandbox=1,

unsubscribeDetectedAt=(null),

billingIssueDetectedAt=(null),

ownershipType=0,

>, "Standard": <RCEntitlementInfo: identifier=Standard,

isActive=0,

willRenew=1,

periodType=0,

latestPurchaseDate=2021-09-21 13:02:24 +0000,

originalPurchaseDate=2021-09-21 08:11:56 +0000,

expirationDate=2021-09-21 13:02:54 +0000,

store=0,

productIdentifier=plan.standard.1month,

isSandbox=1,

unsubscribeDetectedAt=(null),

billingIssueDetectedAt=(null),

ownershipType=0,

>]

2021-09-22 11:37:56.531422+0300 MyApplication[18699:162713] [Purchases] - DEBUG: ℹ️ applicationDidBecomeActive

2021-09-22 11:37:56.775216+0300 MyApplication[18699:162713] [Purchases] - DEBUG: ℹ️ Offerings cache is stale, updating caches

2021-09-22 11:37:56.780389+0300 MyApplication[18699:163172] [Purchases] - DEBUG: ℹ️ API request started: GET /v1/subscribers/$RCAnonymousID:4eed6543ccef43368c5d190402988754/offerings

2021-09-22 11:37:56.781400+0300 MyApplication[18699:163172] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request GET /subscribers/$RCAnonymousID0X0P+04eed6543ccef43368c5d190402988754

2021-09-22 11:37:56.781489+0300 MyApplication[18699:163172] [Purchases] - DEBUG: ℹ️ API request started: GET /v1/subscribers/$RCAnonymousID:4eed6543ccef43368c5d190402988754

2021-09-22 11:37:57.535855+0300 MyApplication[18699:163172] [Purchases] - DEBUG: ℹ️ API request completed with status: GET /v1/subscribers/$RCAnonymousID:4eed6543ccef43368c5d190402988754/offerings 304

2021-09-22 11:37:57.537104+0300 MyApplication[18699:163172] [Purchases] - DEBUG: ℹ️ Requesting products from the store with identifiers: {(

    "plan.standard.6months",

    "plan.standard.1month",

    "plan.advanced.1month",

    "plan.standard.1year",

    "plan.advanced.1year",

    "plan.advanced.6months"

)}

2021-09-22 11:37:57.551464+0300 MyApplication[18699:163153] [Purchases] - DEBUG: ℹ️ Products request finished.

2021-09-22 11:37:57.551606+0300 MyApplication[18699:163153] [Purchases] - DEBUG: 💰 Retrieved SKProducts:

2021-09-22 11:37:57.551784+0300 MyApplication[18699:163153] [Purchases] - DEBUG: 💰 plan.standard.1month - <SKProduct: 0x60000369f200>

2021-09-22 11:37:57.551946+0300 MyApplication[18699:163153] [Purchases] - DEBUG: 💰 plan.advanced.1month - <SKProduct: 0x60000369f180>

2021-09-22 11:37:57.552088+0300 MyApplication[18699:163153] [Purchases] - DEBUG: 💰 plan.standard.6months - <SKProduct: 0x60000369f120>

2021-09-22 11:37:57.552244+0300 MyApplication[18699:163153] [Purchases] - DEBUG: 💰 plan.advanced.6months - <SKProduct: 0x60000369f1a0>

2021-09-22 11:37:57.552354+0300 MyApplication[18699:163153] [Purchases] - DEBUG: 💰 standard.1year - <SKProduct: 0x60000369f7f0>

2021-09-22 11:37:57.552468+0300 MyApplication[18699:163153] [Purchases] - DEBUG: 💰 advanced.1year - <SKProduct: 0x60000369f820>

2021-09-22 11:37:57.552617+0300 MyApplication[18699:163153] [Purchases] - DEBUG: ℹ️ 2 completion handlers waiting on products

2021-09-22 11:37:57.590789+0300 MyApplication[18699:163153] [Purchases] - DEBUG: ℹ️ API request completed with status: GET /v1/subscribers/$RCAnonymousID:4eed6543ccef43368c5d190402988754 304

2021-09-22 11:37:57.593864+0300 MyApplication[18699:163153] [Purchases] - DEBUG: ℹ️ Serial request done: GET /subscribers/$RCAnonymousID0X0P+04eed6543ccef43368c5d190402988754, 0 requests left in the queue

2021-09-22 11:37:59.298466+0300 MyApplication[18699:162713] [Purchases] - DEBUG: ℹ️ Vending Offerings from cache

D
Badge +1

Also, I forgot to add:

All agreements in AppStore account accepted, all this products in Ready to Submit state.

Till 21 September ~04:00 PM all work fine (offerings fetched on device without StoreKit.configuration).

Maybe this help.

 

D
Badge +1

Update: 

Successfully it turned out to run and get a list of offers on another(!) device, I tried launch app on 2 other iPhone’s, and all works now. My device still not fetching offerings (

ryan
Rank
Userlevel 5
Badge +9

The “Requesting products from the store with identifiers: … “ log message indicates that the product IDs were fetched successfully from RevenueCat and now a request is being made from the device to Apple to return the products with those IDs.

I’ve seen some cases before where the iOS product request hangs seemingly forever - there doesn’t appear to be a timeout. Sometimes it could just take a really loooong time. Another thing to try could be to create a new sandbox account in App Store Connect and use that. 

D
Badge +1

The “Requesting products from the store with identifiers: … “ log message indicates that the product IDs were fetched successfully from RevenueCat and now a request is being made from the device to Apple to return the products with those IDs.

I’ve seen some cases before where the iOS product request hangs seemingly forever - there doesn’t appear to be a timeout. Sometimes it could just take a really loooong time. Another thing to try could be to create a new sandbox account in App Store Connect and use that. 

Hello Ryan,

yes that's helping. But for some reasons every sandbox account, after intensive testing stop working. After, I create new sandbox account again.

Andy
Rank
Userlevel 5
Badge +8

@Dmitry I’ve made a fix for purchases-ios. 

It’s available here, and you can get it by using `purchases-ios` branch:

  • `main` branch, for purchases-ios v4 (currently v4 is in beta)
  • `release/3.12.8` if you’re using the v3 version. 

Since we’ve had a tough time trying to reproduce this bug, if you still have access to one of the accounts that reproduces it, would you mind trying out the solution and letting us know if it solves it? It would be immensely helpful. And earn you some swag 😉

 

I made a summary of what we know about the issue here:

Andy

Reply


Terms & ConditionsCookie settings