Solved

Purchase info returned by SDK incorrect

  • 24 November 2021
  • 10 replies
  • 530 views

Badge +6

Users of our Android app are seeing incorrect subscription information. Using SDK version 4.3.0.

 

When debugging this issue we discovered that when calling Purchases.sharedInstance.getPurchaserInfoWith() the function sometimes returns incorrect data. It seems caching logic does not work correctly. For instance the function returns the PurchaseInfo object below when calling it now (nov 24th 20:53 GMT). The request date is 4 days off and there is no firstSeen date. We use these dates to verify trial status.

<PurchaserInfo
     latestExpirationDate: null
    activeSubscriptions:  {},
    activeEntitlements: [],
    entitlements: [],
    nonSubscriptionTransactions: [],
    requestDate: Sat Nov 20 22:39:43 GMT+01:00 2021
    >

When querying the API directly with a GET request from within Postman the result is:

 

{

    "request_date": "2021-11-24T20:02:28Z",

    "request_date_ms": 1637784148481,

    "subscriber": {

        "entitlements": {},

        "first_seen": "2021-11-20T09:49:59Z",

        "last_seen": "2021-11-24T19:31:41Z",

        "management_url": null,

        "non_subscriptions": {},

        "original_app_user_id": "some user id",

        "original_application_version": null,

        "original_purchase_date": null,

        "other_purchases": {},

        "subscriptions": {}

    }

 

So this is correct information.

Any idea how to fix this? If there a way to let the SDK not use the cache? Logcat in Android Studio shows it’s using the cache;

2021-11-24 20:37:58.944 12573-12573/? D/[Purchases] - DEBUG: ℹ️ Vending PurchaserInfo from cache.

2021-11-24 20:37:58.946 12573-12573/? D/[Purchases] - DEBUG: ℹ️ Checking if cache is stale AppInBackground true

icon

Best answer by Silky Apps 17 December 2021, 20:05

View original

10 replies

Userlevel 5
Badge +9

Hey @Silky Apps!

The PurchaserInfo cache is only 5mins so I wouldn’t think that’s the issue.  Have you looked at the debug logs when fetching the purchaser info and checked for any warnings are strange messages there? https://docs.revenuecat.com/docs/debugging

Badge +6

No. Just these 2 lines. Those are shown every time the license page opens and calls Purchases.sharedInstance.getPurchaserInfoWith()

2021-11-24 21:13:21.242 12573-12573/? D/[Purchases] - DEBUG: ℹ️ Vending PurchaserInfo from cache.
2021-11-24 21:13:21.244 12573-12573/? D/[Purchases] - DEBUG: ℹ️ Checking if cache is stale AppInBackground true

The onSuccess callback comes back immediately with the PurchaseInfo object so it’s clearly not making an API call. I extensively checked the whole log but there are no errors. I filtered it with and without the Purchases tag.

I’ve been running a debug version on my device and the trial count down has been stuck on the same date for 4 days. Every time the app opens the license banner is shown on the first screen, which calls Purchases.sharedInstance.getPurchaserInfoWith() to get the subscription state.

I’m pretty convinced it’s not an error in our logic, but due to incorrect PurchaseInfo returned from the SDK. If I run the tests with a correct PurchaseInfo object they pass and the UI is correct. We had multiple users report the issue back to us. They all run release builds on various devices and Android versions.

Userlevel 5
Badge +9

Can you attach the full debug log output as a .txt file, maybe there’s some other logs there that are relevant?

 

The onSuccess callback comes back immediately with the PurchaseInfo object so it’s clearly not making an API call. 

This is expected to return from cache first then make an API call in the background to update the PurchaserInfo object asynchronously for the next time it’s needed.

 

I’m pretty convinced it’s not an error in our logic, but due to incorrect PurchaseInfo returned from the SDK.

The PurchaserInfo gets set from the same API that you were testing in Postman so should be getting updated here. You should check you’re on the latest SDK version but I don’t think we’ve ever had an issue with PurchaserInfo not getting set.

You can also try reproducing this in one of the sample apps: https://docs.revenuecat.com/docs/sample-apps. These are trimmed down examples running the SDK in basic setups but are what we use to try and reproduce bugs. 

Badge +6

Bumped the SDK to v4.5 but does not solve the issue. Discovered that if you call Purchases.sharedInstance.logIn() the SDK always makes an API call and returns the correct PurchaseInfo object in the logIn callback.

So switching to that API for now, since it’s quite crucial to get the correct subscription information from the RC server.

Badge +6

EDIT: damn, Purchases.sharedInstance.logIn() seems to also returned incorrect dataIf I call the function now (25 nov 10:12 GMT) I get this PurchaseInfo object:

<PurchaserInfo
     latestExpirationDate: null
    activeSubscriptions:  {},
    activeEntitlements: [],
    entitlements: [],
    nonSubscriptionTransactions: [],
    requestDate: Wed Nov 24 21:54:02 GMT+01:00 2021
    >

With a requestdate of yesterday.

@ryan any suggestions?

Badge +6

Only when I call  invalidatePurchaserInfoCache() on the SDK the correct PurchaseInfo object gets returned. I see in the logIn function there is a check internally by the SDK calling the currentAppUserID from the identityManager and only proceding when it’s not the current Id.

So logIn() uses the same cache I presume.
 

Badge +6

Continued with the debugging. Found out that even when you invalidate the PurchaserCache, there is an API call made according to the logs:

2021-11-27 17:15:30.156 30373-30546/com.package.app D/[Purchases] - DEBUG: ℹ️ Invalidating PurchaserInfo cache.
2021-11-27 17:15:30.157 30373-30546/com.package.app D/[Purchases] - DEBUG: ℹ️ No cached PurchaserInfo, fetching from network.
2021-11-27 17:15:30.162 30373-30546/com.package.app D/[Purchases] - DEBUG: 😻 PurchaserInfo updated from network.
2021-11-27 17:15:30.204 30373-30546/com.package.app D/[Purchases] - DEBUG: ℹ️ setAttributes called
2021-11-27 17:15:34.735 30373-30555/com.package.app D/[Purchases] - DEBUG: ℹ️ API request started: GET /subscribers/[userId]
2021-11-27 17:15:34.737 30373-30555/com.package.app D/[Purchases] - DEBUG: ℹ️ API request completed with status: GET /subscribers/[userId] 304

But it returns HTTP code 304, meaning there is no (updated) data send and the PurchaserInfo object still has a week old request date in my case.

I get the RC servers have logic to minimize network requests and not send data when the PurcahseInfo object is (largely) identical. This makes sense when the purchase state has not changed. But I would except when an API call is made the request date will be at least supplied. Since this date is used in our logic to determine trial status.

@ryan is there a way around this? Or should I just make a network request to a NTP time server as well, just to make sure we get the actual current time..

Using the device time can be easily manipulated by the user and is not a good solution.

Userlevel 5
Badge +9

Hey @Silky Apps!

It’d still be good to see the full debug log output to see if there’s anything else we can spot. If you want to attach that here or open a ticket with the support team.

I definitely wouldn’t recommend calling .logIn as a replacement for this and you shouldn’t need to invalidate the cache or make your own network request.

The request_date property gets updated each time PurchaserInfo is fetched from the server even if it’s not updated, so if you’re not seeing that designed behavior then it means something else is going on - logs are a great place to begin troubleshooting. 

Userlevel 6
Badge +8

Hey @Silky Apps,

Were you able to get full debug logs for this issue you’re experiencing? As Ryan mentioned, you shouldn’t need to invalidate the cache or call logIn as a replacement. If there’s a bug here, debug logs will help us investigate and address any potential bugs.

Badge +6

Well I stopped debugging and switched to Kronos lib from Lyft to get a reliable timeserver response. Funny thing is when that update was pushed we got a host of new subscribers  in 1 week (70+), because our logic to determine trial state was based on the incorrectly cached Date object from the RC response. The Kronos lib just queries time.google.com, time.apple.com, time.microsoft.com etc.

I’m pretty convinced their is a bug in your SDK’s caching logic. But I don’t have time to do more extensive debugging atm. Maybe later I will.

Reply