Solved

purchaserInfoWithCompletionBlock not called

  • 19 October 2021
  • 19 replies
  • 141 views

Userlevel 2
Badge +4

Using iOS SDK, and just recently, like two weeks ago.  This API is randomly never calling the completion block?

- (void)purchaserInfoWithCompletionBlock:(RCReceivePurchaserInfoBlock)completion

 

This never happened before.

Thanks,

Ilam

icon

Best answer by taquitos 22 October 2021, 00:06

View original

19 replies

Userlevel 2
Badge +4

The end result of this uncompleted block call is users who bought stuff, they find it locked and they need to Restore Purchases (or panic and send me nasty email that I want to charge them twice etc...).  

The workaround I did is to put a flag so I know if the call is not completed, if not completed, which is random and I can’t reproduce consistently, I then make sure users have access to all the features and if after few seconds, I invoke Restore Purchases and things will continue to work fine.

I think it is related to iOS 15 but it is jut my guess (because of the timing).

Userlevel 4
Badge +9

Hey @imougy!

Can you share the SDK version you’re using and the complete debug log output? There don’t seem to be any open bugs related to this but we can take a look here and triage. 

Userlevel 2
Badge +4

version 3.12.6

debug log seems normal.  It is totally random and happens very rare but it seems the occurrence is when I don’t launch the app for a long time

 

Userlevel 2
Badge +4

Here is a log but this log is output when everything is normal, I can’t reproduce the issue, unless I run outside the debugger and I relaunch the app like 100 times or so if I am lucky to get the issue:-

2021-10-18 16:03:08.882990-0700 Stocks Live[3911:280109] [Purchases] - DEBUG: ℹ️ Debug logging enabled

2021-10-18 16:03:08.883090-0700 Stocks Live[3911:280109] [Purchases] - DEBUG: ℹ️ SDK Version - 3.12.6

2021-10-18 16:03:08.883144-0700 Stocks Live[3911:280109] [Purchases] - DEBUG: 👤 Initial App User ID - U10862126809263424902

2021-10-18 16:03:08.886950-0700 Stocks Live[3911:280109] [Purchases] - DEBUG: ℹ️ Requesting products from the store with identifiers: {(

2021-10-18 16:03:09.006884-0700 Stocks Live[3911:280109] [Purchases] - DEBUG: ℹ️ Vending PurchaserInfo from cache.

2021-10-18 16:03:09.007193-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: ℹ️ Products request finished.

2021-10-18 16:03:09.007333-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 Retrieved SKProducts:

2021-10-18 16:03:09.007525-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.6999_1y_1w0 - <SKProduct: 0x2820ec060>

2021-10-18 16:03:09.007659-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.699_1m_1w0 - <SKProduct: 0x2820ec0e0>

2021-10-18 16:03:09.007781-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.AllScanners - <SKProduct: 0x2820f1ee0>

2021-10-18 16:03:09.007899-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.Bundle1 - <SKProduct: 0x2820f1ef0>

2021-10-18 16:03:09.008022-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.Bundle2 - <SKProduct: 0x2820f1f30>

2021-10-18 16:03:09.008136-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.BundleAll - <SKProduct: 0x2820f1f10>

2021-10-18 16:03:09.008288-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.BundleAll1 - <SKProduct: 0x2820f1f00>

2021-10-18 16:03:09.008383-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.BundleAll2 - <SKProduct: 0x2820f1ff0>

2021-10-18 16:03:09.008425-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.Calendar - <SKProduct: 0x2820f2000>

2021-10-18 16:03:09.008528-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.Compare - <SKProduct: 0x2820f2010>

2021-10-18 16:03:09.008560-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.Competitors - <SKProduct: 0x2820f2020>

911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.CryptoScanners - <SKProduct: 0x2820f2030>

2021-10-18 16:03:09.008620-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.DividendHistory - <SKProduct: 0x2820f2040>

2021-10-18 16:03:09.008831-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.ETFHoldings - <SKProduct: 0x2820f2050>

2021-10-18 16:03:09.009752-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.EarningEstimates - <SKProduct: 0x2820f2060>

2021-10-18 16:03:09.009881-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.Educator.Andrew1 - <SKProduct: 0x2820f2070>

2021-10-18 16:03:09.009986-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.Educator.Andrew2 - <SKProduct: 0x2820f2080>

2021-10-18 16:03:09.010083-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.Educator.Andrew3 - <SKProduct: 0x2820f2090>

2021-10-18 16:03:09.010179-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.Educator.Andrew4 - <SKProduct: 0x2820f20a0>

2021-10-18 16:03:09.010276-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.Educator.Andrew5 - <SKProduct: 0x2820f20b0>

2021-10-18 16:03:09.010378-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.Educator.Andrew6 - <SKProduct: 0x2820f20c0>

2021-10-18 16:03:09.010486-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.Educator.Andrew7 - <SKProduct: 0x2820f20d0>

2021-10-18 16:03:09.010671-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.Educator.Andrew8 - <SKProduct: 0x2820f20e0>

2021-10-18 16:03:09.010830-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.Educator.Francis1 - <SKProduct: 0x2820f20f0>

11:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.Educator.Francis2 - <SKProduct: 0x2820f2100>

2021-10-18 16:03:09.011273-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.EnhancedWatchList - <SKProduct: 0x2820f2120>

2021-10-18 16:03:09.011503-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.ExtendedNumbersView - <SKProduct: 0x2820f2130>

2021-10-18 16:03:09.011751-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.ExtendedProfileView - <SKProduct: 0x2820f2140>

2021-10-18 16:03:09.011877-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.GurusPortfolio - <SKProduct: 0x2820f2150>

2021-10-18 16:03:09.012186-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.HeatMap - <SKProduct: 0x2820f2160>

ks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.HideSensitive - <SKProduct: 0x2820f2170>

2021-10-18 16:03:09.012633-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.HotScanners - <SKProduct: 0x2820f2180>

2021-10-18 16:03:09.012669-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.MultipleNewsView - <SKProduct: 0x2820f2190>

2021-10-18 16:03:09.012737-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.NewIPOView - <SKProduct: 0x2820f21a0>

2021-10-18 16:03:09.012851-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.Portfolio - <SKProduct: 0x2820f4010>

2021-10-18 16:03:09.013023-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.PortfolioAllocationCSVExport - <SKProduct: 0x2820f4040>

2021-10-18 16:03:09.013603-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.Pro - <SKProduct: 0x2820e80e0>

2021-10-18 16:03:09.013738-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.ProPlus - <SKProduct: 0x2820e80f0>

2021-10-18 16:03:09.013775-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.RealTimeNASDAQ_NYSE - <SKProduct: 0x2820e8100>

2021-10-18 16:03:09.013945-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.SPOView - <SKProduct: 0x2820e8110>

2021-10-18 16:03:09.014133-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.SentimentInvestor - <SKProduct: 0x2820e8120>

2021-10-18 16:03:09.014289-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.StocktwitsIntegration - <SKProduct: 0x2820e8130>

2021-10-18 16:03:09.015044-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: 💰 com.cinnamonmobile.StocksLive.TDIntegration - <SKProduct: 0x2820e8140>

2021-10-18 16:03:09.015171-0700 Stocks Live[3911:280141] [Purchases] - WARN: 🍎‼️ Invalid Product Identifiers - (

2021-10-18 16:03:09.015286-0700 Stocks Live[3911:280141] [Purchases] - DEBUG: ℹ️ 1 completion handlers waiting on products

2021-10-18 16:03:09.521455-0700 Stocks Live[3911:280109] [Purchases] - DEBUG: ℹ️ applicationDidBecomeActive

2021-10-18 16:03:09.543924-0700 Stocks Live[3911:280152] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request GET /subscribers/U10862126809263424902

2021-10-18 16:03:09.544246-0700 Stocks Live[3911:280152] [Purchases] - DEBUG: ℹ️ API request started: GET /v1/subscribers/U10862126809263424902

2021-10-18 16:03:09.547672-0700 Stocks Live[3911:280152] [Purchases] - DEBUG: ℹ️ There's a request currently running and 0 requests left in the queue, queueing GET /subscribers/U10862126809263424902/offerings

2021-10-18 16:03:10.556240-0700 Stocks Live[3911:280150] [Purchases] - DEBUG: ℹ️ API request completed with status: GET /v1/subscribers/U10862126809263424902 304

2021-10-18 16:03:10.568181-0700 Stocks Live[3911:280150] [Purchases] - DEBUG: ℹ️ Serial request done: GET /subscribers/U10862126809263424902, 1 requests left in the queue

2021-10-18 16:03:10.568373-0700 Stocks Live[3911:280150] [Purchases] - DEBUG: ℹ️ Starting the next request in the queue, <RCHTTPRequest: httpMethod=GET

2021-10-18 16:03:10.583598-0700 Stocks Live[3911:280150] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request GET /subscribers/U10862126809263424902/offerings

2021-10-18 16:03:10.583680-0700 Stocks Live[3911:280150] [Purchases] - DEBUG: ℹ️ API request started: GET /v1/subscribers/U10862126809263424902/offerings

2021-10-18 16:03:10.683827-0700 Stocks Live[3911:280176] [Purchases] - DEBUG: ℹ️ API request completed with status: GET /v1/subscribers/U10862126809263424902/offerings 304

2021-10-18 16:03:10.684322-0700 Stocks Live[3911:280176] [Purchases] - ERROR: 🍎‼️ Error fetching offerings - Error Domain=RCPurchasesErrorDomain Code=23 "There's a problem with your configuration. There are no products registered in the RevenueCat dashboard for your offerings. To configure products, follow the instructions in https://rev.cat/how-to-configure-offerings.

76] [Purchases] - DEBUG: ℹ️ Serial request done: GET /subscribers/U10862126809263424902/offerings, 0 requests left in the queue

Userlevel 1
Badge +1

Heya @imougy, I’m one of the SDK devs, if you can remember, what SDK version you were using before the upgrade? I’m 90% sure we didn’t change anything that would cause something like this, but I want to go through all our releases and see.

Also, I traced the call hierarchy and I don’t see anywhere that we don’t call the completion blocks, so I’m starting to think there could be a deadlocking condition. We did just recently update a lot of how we do network requests, handle responses, and even our caching since we migrated all the things to Swift, but didn’t back-port any of it.

If you have the time, could you try RevenueCat V4 Beta and tell us if it’s still reproducible?

There are a few name changes, but otherwise the API is the same. You can see the changelog

To jump into the beta using Cocoapods:
pod 'RevenueCat', '~> 4.0.0-beta.3'

or SPM, you’ll need to remove the package, and then re-add it, making sure to set `Up to Next Major`  as 4 < 5.0.0

Userlevel 2
Badge +4

 

First, hats off to you guys, the SDK is one of the best I have ever used, really awesome job!

 

I don’t remember the previous version and don’t want to guess. 

 

I just want to assure you that the completion block is not being called.  I call this API on launch only once and it uses to work flawlessly, now it is very rarely failings and I never managed to catch it while debugging, I had to put so many debugging code to figure out that this is what is happening.  My workaround works perfectly, like I mentioned, I wait 2 seconds and check if the completion block is not called l, if so, I call Restore Purchases and this seems to work fine but I wanted you guys to know what is happening. 

 

For your hypothesis of deadlock, I am open to debug if you have suggestions but at the end of the day, the app works fine if this api fails to call me back and users just don’t find their purchases.   One thing I realized, regarding the occurrence of the issue, is if the launched interval from previous launch is more than 5 hours or so, the probability is high of failing. Like I said, I can’t reproduce consistently but usually I can see it happening if the previous launch was a long time ago. 

 

I will use the beta version and let you know. 
 

Thanks again for the follow up. 

Userlevel 2
Badge +4

Tried to get the beta but can’t:-

 

Userlevel 1
Badge +1

🤦‍♂️ Ok, I thought it was `4.0.0` but to resolve the beta, it should be `4.0.0-beta.3`, sorry about that!

 

I definitely believe you about the completion not being called. I suspect it might have to do with how we handle multiple network requests.

Thanks for the extra info on how you repro! 

Userlevel 2
Badge +4

@taquitos , I upgraded to the Beta version and will test.  

I can take some risk and publish to the App Store at one point with the new SDK, do you see any issues with that?  I usually update the app frequently, so when the new RevenueCat SDK comes from Beta, I will update.

 

Will keep you in touch,

Much thanks for your help, though I wish to know the root reason for the issue but that is fine if things are working normal.

Userlevel 1
Badge +1

We have about 12 apps that have shipped with the earlier Betas, and so far so good, no reports of issues 😄 I would ship my own app with this Beta.

Moving forward, we’re going to change a couple function names like `.offerings:completion` to `getOfferings:completion` to help resolve some confusion since it can be tricky for folks to know what we’re talking about when asking for help (Purchases.Offerings object, or Purchases.offering function, etc). The majority of our api changes are 🪨 solid. Functionally speaking, the APIs are only changing in name so you won’t have to worry about reimplementing changed logic.

We really appreciate you going above and beyond here with the reports and testing. We’re still looking into the root cause of this.

Userlevel 2
Badge +4

Hi @taquitos I relaxed my debugging code, in preparation to release to the App Store and the confidence that the Beta is different but sadly today, I opened the app with my account (have full access to everything) and no debugger, and found all my purchases are gone and needed to do manual Restore Purchases :(

I added back the debugging code to see what is going on but I know now that completion block IS called but somehow my purchases are retrieved.  I added code to see if my account return any zero entitlements or zero nonSubscriptionTransactions and will see.  If you have any suggestion for any debugging code to add, please let me know.  Like I said, I can’t reproduce while debugging, just happens any time if I leave the app not launched for a while.

Will keep you posted.

PS: I can give you any account identifier if you like to catch things on your server if you like.  Just let me know.

Userlevel 2
Badge +4

@taquitos So 30 minutes ago, the api returned the entitlement of my account with zero entries.  After Restore Purchases it came back normal. 
I am happy to work with you on the issue, I can pass you the info object or whatever you like.  I am using the latest iOS and latest Xcode and of course the beta you mentioned. 

Userlevel 1
Badge +1

@taquitos So 30 minutes ago, the api returned the entitlement of my account with zero entries.  After Restore Purchases it came back normal. 

Woof. That’s weird. Let me chat with some folks and see how we can help chase this down.

Userlevel 2
Badge +4

I am closing this issue because the completion block is being called.

I will open another issue that highlights the fact that some users, myself, randomly get zero entitlements from time to time (Restore Purchase solves the issue but it is causing panic).

Userlevel 4
Badge +9

Is there any code path that might be calling .logOut() or clearing NSUserDefaults? Either of those could reset the App User ID and require restoring purchases.

Do you happen to have an App User ID that recently ran into this issue and restored? I can check their logs (feel free to DM it do me).

Userlevel 2
Badge +4

HI @ryan, I don’t logout and don’t clear the pref. 
I sent you the user ID by DM. 

The issue just happened 5 minutes ago, hopefully you can shed some light, happy to add any code to make it easier on your side. 

Userlevel 2
Badge +4

@ryan , this user stuck and can’t get his purchases at all, even after deleting the app and reinstalling!

this is his ID: F6862686180809447439

screen shot of the error attached 

Can you please let me know what you can do so I can communicate with him?

Thanks,

Userlevel 1
Badge +1

@ryan , this user stuck and can’t get his purchases at all, even after deleting the app and reinstalling!

this is his ID: F6862686180809447439

screen shot of the error attached 

Can you please let me know what you can do so I can communicate with him?

Thanks,

While we investigate this one, too, I’m going to start updating our error codes to more specifically callout what parts of our validation failed client-side. I know this doesn’t help you immediately, but I hope to have something better than just “Received malformed response from the backend” to point us in the right direction in the future.

Userlevel 2
Badge +4

@taquitos awesome, we are here for the long term. 

Reply