[Closed] Restore purchases not working in Unity IAP (Android)

Unity Services
1

Restoring Transactions does not work (non-consumable purchases).

I delete the game and re-install.
When the game starts, the store successfully initialized and logs can be seen that the purchase EXISTS on the server:

07-28 18:30:20.134: I/UnityIAP(13921): Sku is owned: com.game.mysupergame_donate_pack_2

But ProcessPurchase method is not called, though the documentation is written, it must be called automatically. Manual Restoring Transactions Unity IAP is not provided for Android.

For the sake of experiment, try manually again to buy goods. Reading logs. We see that the goods have ALREADY been bought and then he charged us successfully:

07-29 10:33:07.716: I/UnityIAP(13543): Unable to buy item (response: 7:Item Already Owned)
07-29 10:33:07.716: I/UnityIAP(13543): Product purchased successfully!

Why does not the automatic restoration of purchases and not called ProcessPurchase?

Full logs initialization when you start the game:

    07-28 18:30:20.114: I/UnityIAP(13921): Starting in-app billing setup.
    07-28 18:30:20.122: I/UnityIAP(13921): Billing service connected.
    07-28 18:30:20.123: I/UnityIAP(13921): invoking callback
    07-28 18:30:20.123: I/UnityIAP(13921): Checking for in-app billing 3 support.
    07-28 18:30:20.126: I/Finsky(7529): [2555] com.google.android.finsky.billing.iab.q.a(160): com.game.mysupergame: Account from first account - [xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx]
    07-28 18:30:20.127: I/UnityIAP(13921): In-app billing version 3 supported for com.game.mysupergame
    07-28 18:30:20.129: I/Finsky(7529): [2554] com.google.android.finsky.billing.iab.q.a(160): com.game.mysupergame: Account from first account - [xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx]
    07-28 18:30:20.129: I/UnityIAP(13921): Subscriptions AVAILABLE.
    07-28 18:30:20.130: I/UnityIAP(13921): onIabSetupFinished: 0
    07-28 18:30:20.130: I/UnityIAP(13921): Requesting 4 products
    07-28 18:30:20.130: I/UnityIAP(13921): QueryInventory: 4
    07-28 18:30:20.131: I/UnityIAP(13921): invoking callback
    07-28 18:30:20.131: I/UnityIAP(13921): Querying owned items, item type: inapp
    07-28 18:30:20.131: I/UnityIAP(13921): Package name: com.game.mysupergame
    07-28 18:30:20.131: I/UnityIAP(13921): Calling getPurchases with continuation token: null
    07-28 18:30:20.133: I/Finsky(7529): [2579] com.google.android.finsky.billing.iab.q.a(160): com.game.mysupergame: Account from first account - [xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx]
    07-28 18:30:20.134: I/UnityIAP(13921): Owned items response: 0
    07-28 18:30:20.134: I/UnityIAP(13921): Sku is owned: com.game.mysupergame_donate_pack_2
    07-28 18:30:20.134: I/UnityIAP(13921): Continuation token: null
    07-28 18:30:20.134: I/UnityIAP(13921): Querying SKU details.
    07-28 18:30:20.137: I/Finsky(7529): [2555] com.google.android.finsky.billing.iab.q.a(160): com.game.mysupergame: Account from first account - [xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx]
    07-28 18:30:20.189: I/UnityIAP(13921): Got sku details: SkuDetails:{"productId":"com.game.mysupergame_donate_pack_1","type":"inapp","price":"21,99 Š³Ń€Š½.","price_amount_micros":21990000,"price_currency_code":"UAH","title":"1000 Coins","description":"Coins for ingame purchases"}
    07-28 18:30:20.189: I/UnityIAP(13921): Got sku details: SkuDetails:{"productId":"com.game.mysupergame_donate_pack_2","type":"inapp","price":"43,99 Š³Ń€Š½.","price_amount_micros":43990000,"price_currency_code":"UAH","title":"Ads removing","description":"Remove all Ads in the game"}
    07-28 18:30:20.190: I/UnityIAP(13921): Got sku details: SkuDetails:{"productId":"com.game.mysupergame_donate_pack_2","type":"inapp","price":"43,99 Š³Ń€Š½.","price_amount_micros":43990000,"price_currency_code":"UAH","title":"Ads removing","description":"Remove all Ads in the game"}
    07-28 18:30:20.190: I/UnityIAP(13921): Got sku details: SkuDetails:{"productId":"com.game.mysupergame_donate_pack_3","type":"inapp","price":"149,99 Š³Ń€Š½.","price_amount_micros":149990000,"price_currency_code":"UAH","title":"Coins double + Ads removing","description":"Coins double + Ads removing"}
    07-28 18:30:20.190: I/UnityIAP(13921): Got sku details: SkuDetails:{"productId":"com.game.mysupergame_donate_pack_4","type":"inapp","price":"439,99 Š³Ń€Š½.","price_amount_micros":439990000,"price_currency_code":"UAH","title":"Unlimited fuel + Coins double + Ads removing","description":"Unlimited fuel + Coins double + Ads removing"}
    07-28 18:30:20.190: I/UnityIAP(13921): Querying owned items, item type: subs
    07-28 18:30:20.190: I/UnityIAP(13921): Package name: com.game.mysupergame
    07-28 18:30:20.190: I/UnityIAP(13921): Calling getPurchases with continuation token: null
    07-28 18:30:20.192: I/Finsky(7529): [2554] com.google.android.finsky.billing.iab.q.a(160): com.game.mysupergame: Account from first account - [xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx]
    07-28 18:30:20.193: I/UnityIAP(13921): Owned items response: 0
    07-28 18:30:20.193: I/UnityIAP(13921): Continuation token: null
    07-28 18:30:20.193: I/UnityIAP(13921): Querying SKU details.
    07-28 18:30:20.195: I/Finsky(7529): [2579] com.google.android.finsky.billing.iab.q.a(160): com.game.mysupergame: Account from first account - [xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx]
    07-28 18:30:20.271: I/UnityIAP(13921): onQueryInventoryFinished: true
    07-28 18:30:20.271: I/UnityIAP(13921): Inventory refresh successful. (response: 0:OK)

    07-28 18:30:20.507: I/Unity(13921): OnInitialized: PASS
    07-28 18:30:20.511: I/art(13921): Rejecting re-init on previously-failed class java.lang.Class<org.chromium.content.browser.FloatingWebActionModeCallback>
    07-28 18:30:20.512: I/art(13921): Rejecting re-init on previously-failed class java.lang.Class<org.chromium.content.browser.FloatingWebActionModeCallback>

    07-28 18:30:20.513: I/Unity(13921): 1000 Coins , 21,99 Š³Ń€Š½., price_int21.99, iso: UAH
    07-28 18:30:20.513: I/Unity(13921): Ads removing , 43,99 Š³Ń€Š½., price_int43.99, iso: UAH
    07-28 18:30:20.513: I/Unity(13921): Coins double + Ads removing , 149,99 Š³Ń€Š½., price_int149.99, iso: UAH
    07-28 18:30:20.514: I/Unity(13921): Unlimited fuel + Coins double + Ads removing , 439,99 Š³Ń€Š½., price_int439.99, iso: UAH

Unity 5.3.4
Tested on Samsung Galaxy S5 and Nexus 7 2013 (Android 5).
The application runs on Google Play in alpha.

2

Weā€™re having a very similar-sounding problem here, although the steps to reproduce were slightly different.

Like Nolex, OnInitialize is being called, but ProccessPurchase is not, and when we attempt to purchase the same item again via ā€œstoreController.InitiatePurchaseā€ we get an error from GooglePlay saying that the item has already been purchased (exact string in Japanese: ā€œę—¢ć«ę‰€ęœ‰ęøˆćæć®ć‚¢ć‚¤ćƒ†ćƒ ć§ć™ā€), followed by the callback from the Unity plugin saying the purchase resulted in a failure because we already own the item.

However, the error callback is not followed by the purchase successful callback in our case.

In our case the problem arose after we terminated the app while the GooglePlay ā€œPurchase Successfulā€ prompt was showing. However, we are using Consumable items, but I think internally they are treated very similarly to non-consumables?

We are using:
1.6.0 of UnityIAP.
Android 6.0.1
GalaxyS7 (SCV33)
Unity5.3.5f1
Tests were done in the sandbox environment.

logcat when relaunching the app with the issue, then trying to repurchase:

07-29 20:15:56.059: I/UnityIAP(12251): IAB helper created.
07-29 20:15:56.119: I/UnityIAP(12251): Starting in-app billing setup.
07-29 20:15:56.139: I/UnityIAP(12251): Billing service connected.
07-29 20:15:56.139: I/UnityIAP(12251): invoking callback
07-29 20:15:56.139: I/UnityIAP(12251): Checking for in-app billing 3 support.
07-29 20:15:56.149: I/UnityIAP(12251): In-app billing version 3 supported for jp.co.landho.purchasetest
07-29 20:15:56.149: I/UnityIAP(12251): Subscriptions AVAILABLE.
07-29 20:15:56.149: I/UnityIAP(12251): onIabSetupFinished: 0
07-29 20:15:56.149: I/UnityIAP(12251): Requesting 5 products
07-29 20:15:56.149: I/UnityIAP(12251): QueryInventory: 5
07-29 20:15:56.149: I/UnityIAP(12251): invoking callback
07-29 20:15:56.149: I/UnityIAP(12251): Querying owned items, item type: inapp
07-29 20:15:56.149: I/UnityIAP(12251): Package name: jp.co.landho.purchasetest
07-29 20:15:56.149: I/UnityIAP(12251): Calling getPurchases with continuation token: null
07-29 20:15:56.159: I/UnityIAP(12251): Owned items response: 0
07-29 20:15:56.159: I/UnityIAP(12251): Continuation token: null
07-29 20:15:56.159: I/UnityIAP(12251): Querying SKU details.
07-29 20:15:56.289: I/UnityIAP(12251): Querying owned items, item type: subs
07-29 20:15:56.289: I/UnityIAP(12251): Package name: jp.co.landho.purchasetest
07-29 20:15:56.289: I/UnityIAP(12251): Calling getPurchases with continuation token: null
07-29 20:15:56.289: I/UnityIAP(12251): Owned items response: 0
07-29 20:15:56.289: I/UnityIAP(12251): Continuation token: null
07-29 20:15:56.289: I/UnityIAP(12251): Querying SKU details.
07-29 20:15:56.429: I/UnityIAP(12251): onQueryInventoryFinished: true
07-29 20:15:56.429: I/UnityIAP(12251): Inventory refresh successful. (response: 0:OK)
07-29 20:16:42.919: I/UnityIAP(12251): onPurchaseProduct: jp.co.landho.purchasetest.money240
07-29 20:16:42.919: I/UnityIAP(12251): ITEM TYPE:inapp
07-29 20:16:43.029: I/UnityIAP(12251): invoking callback
07-29 20:16:43.029: I/UnityIAP(12251): Constructing buy intent for jp.co.landho.purchasetest.money240, item type: inapp
07-29 20:16:43.039: I/UnityIAP(12251): Launching buy intent for jp.co.landho.purchasetest.money240. Request code: 999
07-29 20:16:46.599: I/UnityIAP(12251): onActivityResult
07-29 20:16:46.599: I/UnityIAP(12251): Purchase canceled - Response: 7:Item Already Owned
07-29 20:16:46.599: I/UnityIAP(12251): onIabPurchaseFinished: false
07-29 20:16:46.599: I/UnityIAP(12251): User canceled. (response: -1005:User cancelled)
07-29 20:16:46.599: I/UnityIAP(12251): Purchase response code:-1005
07-29 20:17:17.849: I/UnityIAP(12251): onPurchaseProduct: jp.co.landho.purchasetest.money240
07-29 20:17:17.849: I/UnityIAP(12251): ITEM TYPE:inapp
07-29 20:17:17.909: I/UnityIAP(12251): invoking callback
07-29 20:17:17.909: I/UnityIAP(12251): Constructing buy intent for jp.co.landho.purchasetest.money240, item type: inapp
07-29 20:17:17.919: I/UnityIAP(12251): Launching buy intent for jp.co.landho.purchasetest.money240. Request code: 999
07-29 20:17:20.349: I/UnityIAP(12251): onActivityResult
07-29 20:17:20.349: I/UnityIAP(12251): Purchase canceled - Response: 7:Item Already Owned
07-29 20:17:20.349: I/UnityIAP(12251): onIabPurchaseFinished: false
07-29 20:17:20.349: I/UnityIAP(12251): User canceled. (response: -1005:User cancelled)
07-29 20:17:20.349: I/UnityIAP(12251): Purchase response code:-1005
3

Hi @Nolex and @Tarlius

Thanks for reporting this issue, and sorry youā€™re experiencing it! Can you both make sure youā€™re on the most up to date version of IAP and see if it has the same issue? (You can hit Import in the IAP section in the services window, and if there is a new version it will update it). Also @Nolex it looks like your full logs stop after initialization? If you could post a full log that goes through the attempted purchase so we can see the whole chain and compare to Tarliusā€™ that would be helpful. Also are you also testing this in the sandbox environment?

@Tarlius I know sandbox purchases expire, are you uninstalling/reinstalling the app and testing restore immediately after the original purchase of the product?

Its not behavior weā€™ve experienced in any of our tests so we will try and repro it and let you know what we come up with! Thanks so much to both of you for giving us such detailed information, and if you can let me know the answers to the above questions thatā€™d be a big help. Thanks!

1 Like
4

I noticed that there was an upgrade available but since we were not getting the exception it claimed to fix, we assumed it wasnā€™t the same error and it was getting very late here already. However we updated this morning andā€¦ the plot thickensā€¦

Tests until today were done quite close together (within the same day), so I donā€™t think expiry would have been an issue. However, after we updated the plugin and loaded the app for the first time this morning (ie: after the weekend), the purchase was restored successfully. Iā€™m not sure how an expiry would result in restoring successfully, but its the only tested case where an expiry was likely. I took a quick look at the docs for GooglePlay but couldnā€™t find an explicit timeout.

Then we tried:

load app->purchase->kill at ā€œPurchase completeā€ screen->reload app

and it also restored fine. But then we tried:

load app->purchase->suspend at ā€œPurchase completeā€ screen->resume

and we saw the bug againā€¦

So the observed behaviour was ā€œkillā€ is ok, but ā€œsuspend/resumeā€ breaks things. Unfortunately since once we enter the broken state we canā€™t do any more testing, I canā€™t be sure if that means kill is ok and suspend/resume causes the problem, or if its just not 100% either way. Weā€™ve applied for more test IAP item codes, but itā€™ll be a few hours before we can use them.

Our original use case was slightly different to Nolax, in that we were not trying to transfer devices/reinstall, but rather we closed the app with the ā€œpurchase completeā€ (from GooglePlay) popup still showing. However, we tried changing devices today after reproducing the problem on the first device and got similar symptoms, although ultimately it wasnā€™t able to restore the purchase when repurchasing. It looks like in Nolaxā€™ case the purchase was ultimately restored successfully, but Iā€™m not sure. Ours was not.

Here is a log of the updated plugin (1.6.1) running on the same device showing the broken restore:

08-01 10:55:02.039: I/UnityIAP(25582): IAB helper created.
08-01 10:55:02.089: I/UnityIAP(25582): Starting in-app billing setup.
08-01 10:55:02.109: I/UnityIAP(25582): Billing service connected.
08-01 10:55:02.109: I/UnityIAP(25582): invoking callback
08-01 10:55:02.109: I/UnityIAP(25582): Checking for in-app billing 3 support.
08-01 10:55:02.119: I/UnityIAP(25582): In-app billing version 3 supported for jp.co.landho.purchasetest
08-01 10:55:02.129: I/UnityIAP(25582): Subscriptions AVAILABLE.
08-01 10:55:02.129: I/UnityIAP(25582): onIabSetupFinished: 0
08-01 10:55:02.129: I/UnityIAP(25582): Requesting 5 products
08-01 10:55:02.129: I/UnityIAP(25582): QueryInventory: 5
08-01 10:55:02.129: I/UnityIAP(25582): invoking callback
08-01 10:55:02.129: I/UnityIAP(25582): Querying owned items, item type: inapp
08-01 10:55:02.129: I/UnityIAP(25582): Package name: jp.co.landho.purchasetest
08-01 10:55:02.129: I/UnityIAP(25582): Calling getPurchases with continuation token: null
08-01 10:55:02.139: I/UnityIAP(25582): Owned items response: 0
08-01 10:55:02.139: I/UnityIAP(25582): Continuation token: null
08-01 10:55:02.139: I/UnityIAP(25582): Querying SKU details.
08-01 10:55:02.609: I/UnityIAP(25582): Querying owned items, item type: subs
08-01 10:55:02.609: I/UnityIAP(25582): Package name: jp.co.landho.purchasetest
08-01 10:55:02.609: I/UnityIAP(25582): Calling getPurchases with continuation token: null
08-01 10:55:02.609: I/UnityIAP(25582): Owned items response: 0
08-01 10:55:02.609: I/UnityIAP(25582): Continuation token: null
08-01 10:55:02.609: I/UnityIAP(25582): Querying SKU details.
08-01 10:55:02.729: I/UnityIAP(25582): onQueryInventoryFinished: true
08-01 10:55:02.729: I/UnityIAP(25582): Inventory refresh successful. (response: 0:OK)
08-01 10:55:16.169: I/UnityIAP(25582): onPurchaseProduct: jp.co.landho.purchasetest.money240
08-01 10:55:16.169: I/UnityIAP(25582): ITEM TYPE:inapp
08-01 10:55:16.239: I/UnityIAP(25582): invoking callback
08-01 10:55:16.239: I/UnityIAP(25582): Constructing buy intent for jp.co.landho.purchasetest.money240, item type: inapp
08-01 10:55:16.239: I/UnityIAP(25582): Launching buy intent for jp.co.landho.purchasetest.money240. Request code: 999
08-01 10:55:17.969: I/UnityIAP(25582): onActivityResult
08-01 10:55:17.969: I/UnityIAP(25582): Purchase canceled - Response: 7:Item Already Owned
08-01 10:55:17.969: I/UnityIAP(25582): onIabPurchaseFinished: false
08-01 10:55:17.969: I/UnityIAP(25582): User canceled. (response: -1005:User cancelled)
08-01 10:55:17.969: I/UnityIAP(25582): Purchase response code:-1005
08-01 10:55:19.539: I/UnityIAP(25582): onPurchaseProduct: jp.co.landho.purchasetest.money240
08-01 10:55:19.539: I/UnityIAP(25582): ITEM TYPE:inapp
08-01 10:55:19.589: I/UnityIAP(25582): invoking callback
08-01 10:55:19.589: I/UnityIAP(25582): Constructing buy intent for jp.co.landho.purchasetest.money240, item type: inapp
08-01 10:55:19.599: I/UnityIAP(25582): Launching buy intent for jp.co.landho.purchasetest.money240. Request code: 999
08-01 10:55:20.899: I/UnityIAP(25582): onActivityResult
08-01 10:55:20.909: I/UnityIAP(25582): Purchase canceled - Response: 7:Item Already Owned
08-01 10:55:20.909: I/UnityIAP(25582): onIabPurchaseFinished: false
08-01 10:55:20.909: I/UnityIAP(25582): User canceled. (response: -1005:User cancelled)
08-01 10:55:20.909: I/UnityIAP(25582): Purchase response code:-1005

Here is the log from trying to change devices, after the first device started displaying symptoms again:

08-01 11:27:20.327: I/UnityIAP(26743): IAB helper created.
08-01 11:27:20.375: I/UnityIAP(26743): Starting in-app billing setup.
08-01 11:27:20.444: I/UnityIAP(26743): Billing service connected.
08-01 11:27:20.445: I/UnityIAP(26743): invoking callback
08-01 11:27:20.447: I/UnityIAP(26743): Checking for in-app billing 3 support.
08-01 11:27:20.494: I/UnityIAP(26743): In-app billing version 3 supported for jp.co.landho.purchasetest
08-01 11:27:20.497: I/UnityIAP(26743): Subscriptions AVAILABLE.
08-01 11:27:20.498: I/UnityIAP(26743): onIabSetupFinished: 0
08-01 11:27:20.498: I/UnityIAP(26743): Requesting 5 products
08-01 11:27:20.498: I/UnityIAP(26743): QueryInventory: 5
08-01 11:27:20.498: I/UnityIAP(26743): invoking callback
08-01 11:27:20.498: I/UnityIAP(26743): Querying owned items, item type: inapp
08-01 11:27:20.498: I/UnityIAP(26743): Package name: jp.co.landho.purchasetest
08-01 11:27:20.500: I/UnityIAP(26743): Calling getPurchases with continuation token: null
08-01 11:27:20.506: I/UnityIAP(26743): Owned items response: 0
08-01 11:27:20.507: I/UnityIAP(26743): Sku is owned: jp.co.landho.purchasetest.money240
08-01 11:27:20.507: I/UnityIAP(26743): Continuation token: null
08-01 11:27:20.508: I/UnityIAP(26743): Querying SKU details.
08-01 11:27:21.153: I/UnityIAP(26743): Querying owned items, item type: subs
08-01 11:27:21.153: I/UnityIAP(26743): Package name: jp.co.landho.purchasetest
08-01 11:27:21.153: I/UnityIAP(26743): Calling getPurchases with continuation token: null
08-01 11:27:21.157: I/UnityIAP(26743): Owned items response: 0
08-01 11:27:21.157: I/UnityIAP(26743): Continuation token: null
08-01 11:27:21.157: I/UnityIAP(26743): Querying SKU details.
08-01 11:27:21.357: I/UnityIAP(26743): onQueryInventoryFinished: true
08-01 11:27:21.357: I/UnityIAP(26743): Inventory refresh successful. (response: 0:OK)
08-01 11:27:21.490: I/UnityIAP(26743): Finish transaction:kggjhoekdhnmcmbgdfcgfaof.AO-J1OypOhyS-LGB6-wQ6B7e_S9e2OxUpSZ849ATFaXF9uDMC3rNJGc_4UUbrQFlu2rioN0jJ76qXGhJq4JLBVvZ1Siu1hJKP5tgQvdED1FSpMb9VHR4hEmibyg630fsWGsqQqzqvuTCvPoX36cJ59MRPtRB0ZKyOw
08-01 11:27:21.490: I/UnityIAP(26743): Consuming jp.co.landho.purchasetest.money240
08-01 11:27:21.490: I/UnityIAP(26743): invoking callback
08-01 11:27:21.490: I/UnityIAP(26743): Consuming sku: jp.co.landho.purchasetest.money240, token: kggjhoekdhnmcmbgdfcgfaof.AO-J1OypOhyS-LGB6-wQ6B7e_S9e2OxUpSZ849ATFaXF9uDMC3rNJGc_4UUbrQFlu2rioN0jJ76qXGhJq4JLBVvZ1Siu1hJKP5tgQvdED1FSpMb9VHR4hEmibyg630fsWGsqQqzqvuTCvPoX36cJ59MRPtRB0ZKyOw
08-01 11:27:22.065: I/UnityIAP(26743): Error consuming consuming sku jp.co.landho.purchasetest.money240. 8:Item not owned
08-01 11:27:22.066: I/UnityIAP(26743): onConsumeFinished:false
08-01 11:27:22.066: I/UnityIAP(26743): Error consuming sku jp.co.landho.purchasetest.money240 (response: 8:Item not owned)
08-01 11:27:22.066: I/UnityIAP(26743): 8

Attempting to buy again results in the same behaviour as the other device, ā€œItem Already Ownedā€ etc.

Unfortunately, we dropped the ball and didnā€™t log the unexpected success case, nor when it actually failed the first time today :confused: Hopefully when the new test items are approved we can get some more info.

Edit: Quote formatting

5

@erika_d , Hi, thank you!

I updated Unity IAP to last version [1.6.1] - 2016-07-18 and problem solved.
(Services => In-App Purchasing => Import).

Full logs initialization when start the game:

08-01 11:26:38.071: I/Unity(14585): InitializePurchasing is starting...
08-01 11:26:38.354: I/UnityIAP(14585): IAB helper created.
08-01 11:26:38.372: I/art(14585): Background sticky concurrent mark sweep GC freed 46496(2MB) AllocSpace objects, 12(215KB) LOS objects, 22% free, 9MB/11MB, paused 2.929ms total 291.412ms
08-01 11:26:38.476: I/UnityIAP(14585): Starting in-app billing setup.
08-01 11:26:38.477: I/Unity(14585): InitializePurchasing is finish...
08-01 11:26:39.736: I/Choreographer(14585): Skipped 83 frames!  The application may be doing too much work on its main thread.
08-01 11:26:39.736: I/UnityIAP(14585): Billing service connected.
08-01 11:26:39.737: I/UnityIAP(14585): invoking callback
08-01 11:26:39.737: I/UnityIAP(14585): Checking for in-app billing 3 support.
08-01 11:26:39.817: I/Finsky(14391): [4449] com.google.android.finsky.billing.iab.q.a(160): com.game.mysupergame: Account from first account - [xxxxxxxxxxxxxxxxxxxxxx-Hd_84]
08-01 11:26:39.820: I/UnityIAP(14585): In-app billing version 3 supported for com.game.mysupergame
08-01 11:26:39.822: I/Finsky(14391): [4449] com.google.android.finsky.billing.iab.q.a(160): com.game.mysupergame: Account from first account - [xxxxxxxxxxxxxxxxxxxxxx-Hd_84]
08-01 11:26:39.822: I/UnityIAP(14585): Subscriptions AVAILABLE.
08-01 11:26:39.823: I/UnityIAP(14585): onIabSetupFinished: 0
08-01 11:26:39.823: I/UnityIAP(14585): Requesting 4 products
08-01 11:26:39.823: I/UnityIAP(14585): QueryInventory: 4
08-01 11:26:39.824: I/UnityIAP(14585): invoking callback
08-01 11:26:39.824: I/UnityIAP(14585): Querying owned items, item type: inapp
08-01 11:26:39.824: I/UnityIAP(14585): Package name: com.game.mysupergame
08-01 11:26:39.824: I/UnityIAP(14585): Calling getPurchases with continuation token: null
08-01 11:26:39.826: I/Finsky(14391): [4450] com.google.android.finsky.billing.iab.q.a(160): com.game.mysupergame: Account from first account - [xxxxxxxxxxxxxxxxxxxxxx-Hd_84]
08-01 11:26:39.890: I/UnityIAP(14585): Owned items response: 0
08-01 11:26:39.890: I/UnityIAP(14585): Sku is owned: com.game.mysupergame_donate_pack_3
08-01 11:26:39.890: I/UnityIAP(14585): Sku is owned: com.game.mysupergame_donate_pack_2
08-01 11:26:39.890: I/UnityIAP(14585): Continuation token: null
08-01 11:26:39.890: I/UnityIAP(14585): Querying SKU details.
08-01 11:26:39.892: I/Finsky(14391): [4449] com.google.android.finsky.billing.iab.q.a(160): com.game.mysupergame: Account from first account - [xxxxxxxxxxxxxxxxxxxxxx-Hd_84]
08-01 11:26:40.838: I/UnityIAP(14585): Querying owned items, item type: subs
08-01 11:26:40.838: I/UnityIAP(14585): Package name: com.game.mysupergame
08-01 11:26:40.838: I/UnityIAP(14585): Calling getPurchases with continuation token: null
08-01 11:26:40.843: I/Finsky(14391): [4450] com.google.android.finsky.billing.iab.q.a(160): com.game.mysupergame: Account from first account - [xxxxxxxxxxxxxxxxxxxxxx-Hd_84]
08-01 11:26:40.843: I/UnityIAP(14585): Owned items response: 0
08-01 11:26:40.843: I/UnityIAP(14585): Continuation token: null
08-01 11:26:40.843: I/UnityIAP(14585): Querying SKU details.
08-01 11:26:40.849: I/Finsky(14391): [4482] com.google.android.finsky.billing.iab.q.a(160): com.game.mysupergame: Account from first account - [xxxxxxxxxxxxxxxxxxxxxx-Hd_84]
08-01 11:26:40.953: D/GoogleCertificatesImpl(13090): Fetched 318 Google certificates
08-01 11:26:41.320: I/UnityIAP(14585): onQueryInventoryFinished: true
08-01 11:26:41.320: I/UnityIAP(14585): Inventory refresh successful. (response: 0:OK)
08-01 11:26:41.887: I/Unity(14585): OnInitialized: PASS

08-01 11:26:41.894: I/Unity(14585): 1000 Coins , 21,99 Š³Ń€Š½., price_int21.99, iso: UAH, product.transactionID:
08-01 11:26:41.894: I/Unity(14585): Ads removing , 43,99 Š³Ń€Š½., price_int43.99, iso: UAH, product.transactionID: gofmjgeddgkddohFREEr@#$!@#1e551X5goGWJtYvg9gX_ldfMf9popEKH-tzwQRVMuobh0VX0TUG7JQWERQERDSAFAfdXy5k0d8yftDyvy5WuoCvFeawbPiXlEVknFTSYshD8Rfk4LUmR0zIahhcJl3FffI9zeAxDFDFj7bEHy7eYI2BEPlBQtXTmyGamXqsChFEduSH8
08-01 11:26:41.894: I/Unity(14585): Coins double + Ads removing , 149,99 Š³Ń€Š½., price_int149.99, iso: UAH, product.transactionID: mnkgkagajkpmhmepngpccnFDFDF45345DFRETREo3TtxfCg412Ior_uh0j68_XA4HxLauGrzjKumwW_AiTt2-Tl_J3EobB1JCCVSrlDsqThSjnO1nju3SRSzWMADEs0XWp6I3vn7W3vTEiHQWERWERWQERfdfsdf-a-iaieEFdgdTPX8Pw3oemTaM1gLU3EgnWqczbnJBK79fGjHRnKvT32ai_GY1U4
08-01 11:26:41.895: I/Unity(14585): Unlimited fuel + Coins double + Ads removing , 439,99 Š³Ń€Š½., price_int439.99, iso: UAH, product.transactionID:

08-01 11:26:41.924: I/Unity(14585): ProcessPurchase is starting...
08-01 11:26:41.960: I/Unity(14585): ProcessPurchase: SUCCESS. Product: Remove Ads
08-01 11:26:42.007: I/UnityIAP(14585): Finish transaction:gofmjge234234hnomnmhkdi.AO-J1Ozqc1e551X5goGWJzWEr@#45X_ldfMf9popEKH-t452435Muobh0VX0TUG7J8Q2QSRx1dXy5k0d8yftDyvy5WuoCvFeawbPiXlEasdf234hD8Rfk4LUmR0zIahhcJl3FffI9zeAxbblXyrgj7bEHy7eYI2asdfsfFFErXqsChFEduSH8

08-01 11:26:42.011: I/Unity(14585): ProcessPurchase is starting...
08-01 11:26:42.011: I/Unity(14585): ProcessPurchase: SUCCESS. Product: Coins Doubler + Remove Ads
08-01 11:26:42.015: I/UnityIAP(14585): Finish transaction:mnkgkasdafasdfngpccnbc.AO-J1Oyo3TtxfCg412Ior_uh0j68_XA4HxLauGrzjKumwW_AiTt2-Tl_J3EobB1JCCVSrlDsqThSjnO1nju3SRSzWMADEs0tryrty45654EiHfubcPXf2345fg21iaieEFdgdTPX8Pw3oemTarty42439fGjHRnKvT32ai_GY1U4
1 Like
6

Weā€™ve done more tests our end and I think weā€™ve worked out the fail case.

1.6.1 seems to have made it harder to reproduce, but we found that:

Open App ā†’ Purchase ā†’ Wait for Purchase Complete popup ā†’ Suspend with home button ā†’ Resume by pressing app icon

will cause the call to not come, putting ā€œNull data in IAB result (response: -1002:Bad response received)ā€ onto the log.

However, resuming via the Overview menu (the activity list/etc) apparently doesnā€™t cause the problem, and neither does killing the app and restarting new.

Trying to purchase the item again with the app in this state causes it to fail with the already purchased problem, but if you kill the app and restart fresh it gets restored as expected.

Knowing this, we tried recalling initialise in the callback if the error code was -1002, which allowed us to workaround the issue for the time being. Here is a log of this case, starting from the purchase:

08-02 12:47:54.064: I/UnityIAP(12286): onPurchaseProduct: jp.co.landho.purchasetest.money240
08-02 12:47:54.064: I/UnityIAP(12286): ITEM TYPE:inapp
08-02 12:47:54.124: I/UnityIAP(12286): invoking callback
08-02 12:47:54.124: I/UnityIAP(12286): Constructing buy intent for jp.co.landho.purchasetest.money240, item type: inapp
08-02 12:47:54.124: I/UnityIAP(12286): Launching buy intent for jp.co.landho.purchasetest.money240. Request code: 999
08-02 12:48:00.424: I/UnityIAP(12286): onActivityResult
08-02 12:48:00.424: I/UnityIAP(12286): onIabPurchaseFinished: false
08-02 12:48:00.424: I/UnityIAP(12286): Null data in IAB result (response: -1002:Bad response received)
08-02 12:48:00.424: I/UnityIAP(12286): Purchase response code:-1002

// Broken state. Further buying returns "Already Owned"
// Worked around with something like
// if error is PurchaseFailureReason.Unknown Initialize()
// to continue:

08-02 12:48:00.714: I/UnityIAP(12286): Requesting 5 products
08-02 12:48:00.714: I/UnityIAP(12286): QueryInventory: 5
08-02 12:48:00.714: I/UnityIAP(12286): invoking callback
08-02 12:48:00.714: I/UnityIAP(12286): Querying owned items, item type: inapp
08-02 12:48:00.714: I/UnityIAP(12286): Package name: jp.co.landho.purchasetest
08-02 12:48:00.714: I/UnityIAP(12286): Calling getPurchases with continuation token: null
08-02 12:48:00.714: I/UnityIAP(12286): Owned items response: 0
08-02 12:48:00.714: I/UnityIAP(12286): Sku is owned: jp.co.landho.purchasetest.money240
08-02 12:48:00.714: I/UnityIAP(12286): Continuation token: null
08-02 12:48:00.714: I/UnityIAP(12286): Querying SKU details.
08-02 12:48:00.784: I/UnityIAP(12286): Querying owned items, item type: subs
08-02 12:48:00.784: I/UnityIAP(12286): Package name: jp.co.landho.purchasetest
08-02 12:48:00.784: I/UnityIAP(12286): Calling getPurchases with continuation token: null
08-02 12:48:00.784: I/UnityIAP(12286): Owned items response: 0
08-02 12:48:00.784: I/UnityIAP(12286): Continuation token: null
08-02 12:48:00.784: I/UnityIAP(12286): Querying SKU details.
08-02 12:48:00.834: I/UnityIAP(12286): onQueryInventoryFinished: true
08-02 12:48:00.834: I/UnityIAP(12286): Inventory refresh successful. (response: 0:OK)
08-02 12:48:01.204: I/UnityIAP(12286): Finish transaction:malknhahcpkadododhfhndbc.AO-J1OyPif-fHiSnzQ-iPiWLDHMhdOVkY4BH_EtakCp8x8wbIrWAdItsiVgbKK8vFb8I9o-r6ej_cjZ0bVVQ3S7t85MTo513Y05SeK8zuyDc8ktDzi30533jI6uDs8VYGut613xu8wbATU6Sx0R5TtzkNJaOYcb90Q
08-02 12:48:01.204: I/UnityIAP(12286): Consuming jp.co.landho.purchasetest.money240
08-02 12:48:01.204: I/UnityIAP(12286): invoking callback
08-02 12:48:01.204: I/UnityIAP(12286): Consuming sku: jp.co.landho.purchasetest.money240, token: malknhahcpkadododhfhndbc.AO-J1OyPif-fHiSnzQ-iPiWLDHMhdOVkY4BH_EtakCp8x8wbIrWAdItsiVgbKK8vFb8I9o-r6ej_cjZ0bVVQ3S7t85MTo513Y05SeK8zuyDc8ktDzi30533jI6uDs8VYGut613xu8wbATU6Sx0R5TtzkNJaOYcb90Q
08-02 12:48:01.924: I/UnityIAP(12286): Successfully consumed sku: jp.co.landho.purchasetest.money240
08-02 12:48:01.924: I/UnityIAP(12286): onConsumeFinished:true
08-02 12:48:01.924: I/UnityIAP(12286): Successful consume of sku jp.co.landho.purchasetest.money240 (response: 0:OK)
08-02 12:48:01.924: I/UnityIAP(12286): 0
1 Like
7

Hi @Tarlius ,

Thank you for the error log and the reproducible steps. Iā€™m glad you were able to come up with a workaround, for while we look into it. I believe we recently just did some work to make sure pausing/resuming didnā€™t break, but perhaps that was on a specific case that isnā€™t covered here. Iā€™ll see if we can duplicate the issue using these steps and let you know how it goes.

8

Hi @Tarlius ,

I was just re-reading your post and I did want to mention a potential problem with your workaround: IAP doesnā€™t support re-initialization, so Iā€™m concerned that when you get the error code and then reinitialize IAP that it may cause some issues, particularly weā€™ve seen it cause issues with not reporting future errors. We will definitely look and see if we can reproduce the issue you experienced!

9

Hi @Tarlius ,

I wanted to follow up with you on this. We recently released IAP 1.7 and it included some fixes for issues with suspending/resuming apps. Have you updated to the new version and did it fix your issues?

10

Sorry about the delay in replying, weā€™ve been pretty busy here.

We just repeated all the tests on 1.8.1 and could no longer reproduce any of the bugs! :smile:

1 Like
11

Hi, I have latest version of Unity IAP. But still I am unable to get ProcessPurchase Method for already purchased NonConsumable items. Following are the logs:

02-17 12:11:31.697 10007-10778/? I/UnityAds: com.unity3d.ads.api.Sdk.logInfo() (line:68) :: Received configuration with 2 placements
02-17 12:11:31.752 10007-10098/? I/Unity: Overriding Google AppId: 589b5d2343150f71c8ac861f
02-17 12:11:31.885 10007-10007/? D/Unity: CBPlugin: Plugin Initialized
02-17 12:11:32.104 10007-10098/? I/UnityIAP: IAB helper created.
02-17 12:11:32.244 10007-10098/? I/UnityIAP: Starting in-app billing setup.
02-17 12:11:32.281 27039-27091/? D/FileShieldService: onPreFileScan:/storage/emulated/legacy/Android/data/com.cowboy.horse.racing.simulator/cache/UnityAdsCache/UnityAdsStorage-private-data.json, 288
02-17 12:11:32.291 10007-10007/? I/UnityIAP: Billing service connected.
02-17 12:11:32.292 10007-10810/? I/UnityIAP: invoking callback
02-17 12:11:32.292 10007-10810/? I/UnityIAP: Checking for in-app billing 3 support.
02-17 12:11:32.298 10007-10810/? I/UnityIAP: In-app billing version 3 supported for com.cowboy.horse.racing.simulator
02-17 12:11:32.303 10007-10810/? I/UnityIAP: Subscriptions AVAILABLE.
02-17 12:11:32.305 10007-10810/? I/UnityIAP: VR supported.
02-17 12:11:32.306 10007-10810/? I/UnityIAP: onIabSetupFinished: 0
02-17 12:11:32.306 10007-10810/? I/UnityIAP: Requesting 5 products
02-17 12:11:32.306 10007-10810/? I/UnityIAP: QueryInventory: 5
02-17 12:11:32.307 10007-10810/? I/UnityIAP: invoking callback
02-17 12:11:32.308 10007-10810/? I/UnityIAP: Querying owned items, item type: inapp
02-17 12:11:32.308 10007-10810/? I/UnityIAP: Package name: com.cowboy.horse.racing.simulator
02-17 12:11:32.308 10007-10810/? I/UnityIAP: Calling getPurchases with continuation token: null
02-17 12:11:32.314 10007-10810/? I/UnityIAP: Owned items response: 0
02-17 12:11:32.314 10007-10810/? I/UnityIAP: Sku is owned: com.bag.derby.horse.racing.hunt.noads
02-17 12:11:32.314 10007-10810/? I/UnityIAP: Sku is owned: com.bag.derby.horse.racing.flat
02-17 12:11:32.314 10007-10810/? I/UnityIAP: Continuation token: null
02-17 12:11:32.314 10007-10810/? I/UnityIAP: Querying SKU details.
02-17 12:11:32.319 868-2088/? V/WindowManager: Adding window Window{1dd59529 u0 PopupWindow:1b3484e2} at 9 of 16 (after Window{36876d35 u0 com.cowboy.horse.racing.simulator/com.unity3d.player.UnityPlayerNativeActivity})
02-17 12:11:32.326 10007-10007/? D/AdsUnity: Calling loadAd() on Android
02-17 12:11:32.492 10007-10778/? I/UnityAds: com.unity3d.ads.api.Sdk.logInfo() (line:68) :: Requesting ad plan from https://adserver.unityads.unity3d.com/games/1207428/fill?advertisingTrackingId=7966181b-34b3-4ca9-ae3a-0cc90ef86a85&limitAdTracking=false&deviceMake=OPPO&deviceModel=A1601&platform=android&screenDensity=320&screenWidth=1280&screenHeight=720&sdkVersion=2007&screenSize=268435554&apiLevel=22&connectionType=cellular&networkType=0&gamerId=5874e09b3540f5f202148919
02-17 12:11:32.561 10007-10810/? I/UnityIAP: Querying owned items, item type: subs
02-17 12:11:32.561 10007-10810/? I/UnityIAP: Package name: com.cowboy.horse.racing.simulator
02-17 12:11:32.561 10007-10810/? I/UnityIAP: Calling getPurchases with continuation token: null
02-17 12:11:32.565 10007-10810/? I/UnityIAP: Owned items response: 0
02-17 12:11:32.565 10007-10810/? I/UnityIAP: Continuation token: null
02-17 12:11:32.565 10007-10810/? I/UnityIAP: Querying SKU details.
02-17 12:11:32.586 10007-10810/? I/UnityIAP: onQueryInventoryFinished: true
02-17 12:11:32.586 10007-10810/? I/UnityIAP: Inventory refresh successful. (response: 0:OK)
02-17 12:11:32.734 10007-10098/? I/Unity: Already recorded transaction cpiodpkdpddffgelobleekdg.AO-J1OyLRHonQ6_0DT56p-vxQ3M6zVGoVgnTFabx4Fmg0CrVcm2HOaRsYDo3X_o59iq3LOZJm6yHIEak3unNIx9XxWz_hUdX7-77qMmUImDk843oJU34JLnV6u8s8W1uPBcQMGZD6VSoMJG_3_G2JsSIqb0HwC-MrCOIW6Si97eZ9hChY37KKQ8
02-17 12:11:32.736 10007-10098/? I/UnityIAP: Finish transaction:cpiodpkdpddffgelobleekdg.AO-J1OyLRHonQ6_0DT56p-vxQ3M6zVGoVgnTFabx4Fmg0CrVcm2HOaRsYDo3X_o59iq3LOZJm6yHIEak3unNIx9XxWz_hUdX7-77qMmUImDk843oJU34JLnV6u8s8W1uPBcQMGZD6VSoMJG_3_G2JsSIqb0HwC-MrCOIW6Si97eZ9hChY37KKQ8
02-17 12:11:32.737 10007-10098/? I/Unity: Already recorded transaction imfoijoobfnnckcpomaicbod.AO-J1Owl9cA5R9iKC4HMC9YhMDEKgmQc2QSHxwDtFtdipnCbZf15FCJU6C52ItIkZsDu8Z-9q7LorG0H8Jc14CqH2v83Avs5KtwEZzmVibxBqvpCsPodmTxlxS-ELdu0H1f6Jw77FVkdCx101XuRCOtEmD6YqiS3eN2za0jhA2RLQxJfMVkptt0
02-17 12:11:32.737 10007-10098/? I/UnityIAP: Finish transaction:imfoijoobfnnckcpomaicbod.AO-J1Owl9cA5R9iKC4HMC9YhMDEKgmQc2QSHxwDtFtdipnCbZf15FCJU6C52ItIkZsDu8Z-9q7LorG0H8Jc14CqH2v83Avs5KtwEZzmVibxBqvpCsPodmTxlxS-ELdu0H1f6Jw77FVkdCx101XuRCOtEmD6YqiS3eN2za0jhA2RLQxJfMVkptt0
02-17 12:11:32.990 10007-10778/? I/UnityAds: com.unity3d.ads.api.Sdk.logInfo() (line:68) :: Unity Ads server returned game advertisement for AB Group 17
02-17 12:11:33.233 10007-10007/? D/WebView: evaluateJavascript=javascript:window.nativebridge.handleCallback([["65","OK",["\/storage\/emulated\/0\/Android\/data\/com.cowboy.horse.racing.simulator\/cache\/UnityAdsCache\/UnityAdsCache-b74f91f1f585e78a5999f721577a0cf47aa0f9c0914cf359a8e5ede844a778c7.mp4"]]]);
02-17 12:11:33.504 10007-10007/? D/WebView: evaluateJavascript=javascript:window.nativebridge.handleCallback([["71","OK",["\/storage\/emulated\/0\/Android\/data\/com.cowboy.horse.racing.simulator\/cache\/UnityAdsCache\/UnityAdsCache-932ace505d102ae5555fa0c463ff5a9fa3eefb962735e94cbbfdceb802ecd87b.png"]]]);
02-17 12:11:33.775 10007-10007/? D/WebView: evaluateJavascript=javascript:window.nativebridge.handleCallback([["77","OK",["\/storage\/emulated\/0\/Android\/data\/com.cowboy.horse.racing.simulator\/cache\/UnityAdsCache\/UnityAdsCache-3e1d1d5507815e1ce4965b9c1e92eef6a6d73eea0589890d3236973c24bf659c.jpg"]]]);
02-17 12:11:33.989 27039-27091/? D/FileShieldService: onPreFileScan:/storage/emulated/legacy/Android/data/com.cowboy.horse.racing.simulator/cache/UnityAdsCache/UnityAdsStorage-private-data.json, 288
02-17 12:11:34.049 10007-10007/? D/WebView: evaluateJavascript=javascript:window.nativebridge.handleCallback([["83","OK",["\/storage\/emulated\/0\/Android\/data\/com.cowboy.horse.racing.simulator\/cache\/UnityAdsCache\/UnityAdsCache-f4c59f48c11b674899bea014218531d8b0b18d0af432f7dba6d4e01a0af6836d.jpg"]]]);
02-17 12:11:40.672 868-1151/? I/PPS: [PPSNotifyAppState] nPackNum:4, pack:com.cowboy.horse.racing.simulator, com:com.unity3d.player.UnityPlayerNativeActivity, state:0, pid:0, last_boost_tid:-1
02-17 12:11:40.728 868-2011/? I/PPS: [PPSNotifyAppState] nPackNum:4, pack:com.cowboy.horse.racing.simulator, com:com.unity3d.player.UnityPlayerNativeActivity, state:4, pid:0, last_boost_tid:-1
02-17 12:11:41.089 27039-27091/? D/FileShieldService: onPreFileScan:/storage/emulated/legacy/Android/data/com.cowboy.horse.racing.simulator/files/Unity/2f0b6273-bcfb-4acb-9ca6-76166793a7dd/Analytics/values, 288
02-17 12:11:41.089 27039-27091/? D/FileShieldService: onPreFileScan:/storage/emulated/legacy/Android/data/com.cowboy.horse.racing.simulator/files/Unity/2f0b6273-bcfb-4acb-9ca6-76166793a7dd/Analytics/ArchivedEvents/148731548300001.f9338afa/s, 288
02-17 12:11:41.089 27039-27091/? D/FileShieldService: onPreFileScan:/storage/emulated/legacy/Android/data/com.cowboy.horse.racing.simulator/files/Unity/2f0b6273-bcfb-4acb-9ca6-76166793a7dd/Analytics/ArchivedEvents/148731548300001.f9338afa/e, 288
02-17 12:11:41.705 868-1967/? V/WindowManager: Changing focus from Window{36876d35 u0 com.cowboy.horse.racing.simulator/com.unity3d.player.UnityPlayerNativeActivity} to Window{3a6891ab u0 Keyguard} Callers=com.android.server.wm.WindowManagerService.relayoutWindow:3823 com.android.server.wm.Session.relayout:203 android.view.IWindowSession$Stub.onTransact:273 com.android.server.wm.Session.onTransact:136
02-17 12:13:39.259 868-887/? I/PPS: [PPSNotifyAppState] nPackNum:4, pack:com.cowboy.horse.racing.simulator, com:com.unity3d.player.UnityPlayerNativeActivity, state:1, pid:0, last_boost_tid:-1
02-17 12:13:39.276 10007-10007/? V/PhoneWindow: DecorView setVisiblity: visibility = 0 ,Parent =ViewRoot{2b33fa0e com.cowboy.horse.racing.simulator/com.unity3d.player.UnityPlayerNativeActivity,ident = 0}, this =com.android.internal.policy.impl.PhoneWindow$DecorView{2402fef8 V.E..... R.....I. 0,0-720,1280}
02-17 12:13:39.321 868-2088/? V/WindowManager: Changing focus from Window{3a6891ab u0 Keyguard} to Window{36876d35 u0 com.cowboy.horse.racing.simulator/com.unity3d.player.UnityPlayerNativeActivity} Callers=com.android.server.wm.WindowManagerService.relayoutWindow:3823 com.android.server.wm.Session.relayout:203 android.view.IWindowSession$Stub.onTransact:273 com.android.server.wm.Session.onTransact:136
02-17 12:13:39.359 868-905/? I/WindowManager: Gaining focus: Window{36876d35 u0 com.cowboy.horse.racing.simulator/com.unity3d.player.UnityPlayerNativeActivity}
02-17 12:13:39.987 27039-27091/? D/FileShieldService: onPreFileScan:/storage/emulated/legacy/Android/data/com.cowboy.horse.racing.simulator/files/Unity/2f0b6273-bcfb-4acb-9ca6-76166793a7dd/Analytics/values, 288
02-17 12:13:40.486 27039-27091/? D/FileShieldService: onPreFileScan:/storage/emulated/legacy/Android/data/com.cowboy.horse.racing.simulator/files/Unity/2f0b6273-bcfb-4acb-9ca6-76166793a7dd/Analytics/ArchivedEvents/148731548300001.f9338afa_tmp/s_tmp, 288
02-17 12:13:40.486 27039-27091/? D/FileShieldService: onPreFileScan:/storage/emulated/legacy/Android/data/com.cowboy.horse.racing.simulator/files/Unity/2f0b6273-bcfb-4acb-9ca6-76166793a7dd/Analytics/ArchivedEvents/148731548300001.f9338afa_tmp/e_tmp, 288
02-17 12:13:44.571 10007-10098/? I/UnityIAP: isUnityVrEnabled = false
02-17 12:13:44.572 10007-10098/? I/UnityIAP: onPurchaseProduct: com.bag.derby.horse.racing.hunt.noads
02-17 12:13:44.572 10007-10098/? I/UnityIAP: ITEM TYPE:inapp
02-17 12:13:44.589 10007-10098/? I/Unity: purchase({0}): com.bag.derby.horse.racing.hunt.noads
02-17 12:13:44.686 868-887/? I/PPS: [PPSNotifyAppState] nPackNum:4, pack:com.cowboy.horse.racing.simulator, com:com.unity3d.player.UnityPlayerNativeActivity, state:0, pid:0, last_boost_tid:-1
02-17 12:13:44.692 10007-10007/? I/Unity Purchasing: Creating purchase activity
02-17 12:13:44.695 10007-10810/? I/UnityIAP: invoking callback
02-17 12:13:44.695 10007-10810/? I/UnityIAP: Constructing buy intent for com.bag.derby.horse.racing.hunt.noads, item type: inapp
02-17 12:13:44.725 10007-10810/? I/UnityIAP: onIabPurchaseFinished: true
02-17 12:13:44.725 10007-10810/? I/UnityIAP: Unable to buy item (response: 7:Item Already Owned)
02-17 12:13:44.725 10007-10810/? I/UnityIAP: Product purchased successfully!
02-17 12:13:44.725 10007-10810/? I/UnityIAP: NotifyUnityOfPurchase
02-17 12:13:44.738 868-888/? I/PPS: [PPSNotifyAppState] nPackNum:4, pack:com.cowboy.horse.racing.simulator, com:com.unity3d.player.UnityPlayerNativeActivity, state:1, pid:0, last_boost_tid:-1
02-17 12:13:44.751 10007-10007/? V/PhoneWindow: DecorView setVisiblity: visibility = 0 ,Parent =ViewRoot{2b33fa0e com.cowboy.horse.racing.simulator/com.unity3d.player.UnityPlayerNativeActivity,ident = 0}, this =com.android.internal.policy.impl.PhoneWindow$DecorView{2402fef8 V.E..... R.....I. 0,0-1280,720}
02-17 12:13:44.781 10007-10007/? I/UnityIAP: onActivityResult
02-17 12:13:44.796 10007-10098/? I/Unity: Already recorded transaction imfoijoobfnnckcpomaicbod.AO-J1Owl9cA5R9iKC4HMC9YhMDEKgmQc2QSHxwDtFtdipnCbZf15FCJU6C52ItIkZsDu8Z-9q7LorG0H8Jc14CqH2v83Avs5KtwEZzmVibxBqvpCsPodmTxlxS-ELdu0H1f6Jw77FVkdCx101XuRCOtEmD6YqiS3eN2za0jhA2RLQxJfMVkptt0
02-17 12:13:44.799 10007-10098/? I/UnityIAP: Finish transaction:imfoijoobfnnckcpomaicbod.AO-J1Owl9cA5R9iKC4HMC9YhMDEKgmQc2QSHxwDtFtdipnCbZf15FCJU6C52ItIkZsDu8Z-9q7LorG0H8Jc14CqH2v83Avs5KtwEZzmVibxBqvpCsPodmTxlxS-ELdu0H1f6Jw77FVkdCx101XuRCOtEmD6YqiS3eN2za0jhA2RLQxJfMVkptt0
02-17 12:13:45.611 27039-27091/? D/FileShieldService: onPreFileScan:/storage/emulated/legacy/Android/data/com.cowboy.horse.racing.simulator/files/Unity/2f0b6273-bcfb-4acb-9ca6-76166793a7dd/Analytics/values, 288
02-17 12:13:45.611 27039-27091/? D/FileShieldService: onPreFileScan:/storage/emulated/legacy/Android/data/com.cowboy.horse.racing.simulator/files/Unity/2f0b6273-bcfb-4acb-9ca6-76166793a7dd/Analytics/ArchivedEvents/148731562400002.f9338afa/s, 288
02-17 12:13:46.258 27039-27091/? D/FileShieldService: onPreFileScan:/storage/emulated/legacy/Android/data/com.cowboy.horse.racing.simulator/files/Unity/2f0b6273-bcfb-4acb-9ca6-76166793a7dd/Analytics/ArchivedEvents/148731562400002.f9338afa_tmp/s_tmp, 288
02-17 12:13:46.258 27039-27091/? D/FileShieldService: onPreFileScan:/storage/emulated/legacy/Android/data/com.cowboy.horse.racing.simulator/files/Unity/2f0b6273-bcfb-4acb-9ca6-76166793a7dd/Analytics/ArchivedEvents/148731562400002.f9338afa_tmp/e_tmp, 288
02-17 12:14:08.123 868-1964/? I/PPS: [PPSNotifyAppState] nPackNum:4, pack:com.cowboy.horse.racing.simulator, com:com.unity3d.player.UnityPlayerNativeActivity, state:0, pid:0, last_boost_tid:-1
02-17 12:14:08.188 868-2086/? I/PPS: [PPSNotifyAppState] nPackNum:4, pack:com.cowboy.horse.racing.simulator, com:com.unity3d.player.UnityPlayerNativeActivity, state:4, pid:0, last_boost_tid:-1
02-17 12:14:08.551 27039-27091/? D/FileShieldService: onPreFileScan:/storage/emulated/legacy/Android/data/com.cowboy.horse.racing.simulator/files/Unity/2f0b6273-bcfb-4acb-9ca6-76166793a7dd/Analytics/values, 288
02-17 12:14:08.887 868-2051/? V/WindowManager: Changing focus from Window{36876d35 u0 com.cowboy.horse.racing.simulator/com.unity3d.player.UnityPlayerNativeActivity} to Window{318e1868 u0 Keyguard} Callers=com.android.server.wm.WindowManagerService.relayoutWindow:3823 com.android.server.wm.Session.relayout:203 android.view.IWindowSession$Stub.onTransact:273 com.android.server.wm.Session.onTransact:136
12

Iā€™m with the same problemā€¦ =/

ProcessPurchase is not being called. How can we call it manually at startup?

Everything was setup in last week, all code in current versions. I bough an item in my app (published app, no testing account) and I cannot restore it after uninstalling/reinstalling. ProcessPurchase is not called until I make another purchase. In editor, ProcessPurchase is only called if I click to buy an item (since in editor it always completes the fake purchase).

Is there a way to call it manually on initialization?

This is so frustrating, I cannot rely on this to include this feature in my app yet. 3 days searching for a solution and I cannot find anything that workā€¦ For now my users havenā€™t complained, but certainly they will do as soon as they reinstall the app or use another device.

My code is as follows. That player prefs I set just to check if there is something wrong with my string comparisonsā€¦ So it will set that option to 0, this is faster to test on my device and also on editor (just by seeing that in my settings screen). But it never changes! So I conclude that ProcessPurchase is not being automatically called. The function SalvaDoador() just saves another playerprefs for any purchase made (Iā€™m using it for ā€œdonationsā€-like payments for now).

I did not bought any other item yet, but the Google Play payment screen shows up when I click on some buy button; their captions are updated with text/price at startup, so yes, it is started and working. Just the ProcessPurchase that is not being called.

public PurchaseProcessingResult ProcessPurchase(PurchaseEventArgs args)
        {

            PlayerPrefs.SetInt("mostrarFPS", 0);
          
            if (String.Equals(args.purchasedProduct.definition.id, kDoar1, StringComparison.Ordinal))
            {
                SalvaDoador ();
                txtBotao1.text = "Thanks!";
                MsgObrigado ("1");
                //Doou 1
                Debug.LogWarning("Doou 1");
            }
            else if (String.Equals(args.purchasedProduct.definition.id, kDoar2, StringComparison.Ordinal))
            {
                SalvaDoador ();
                txtBotao2.text = "Thanks!";
                MsgObrigado ("1");
                //doou 2
                Debug.LogWarning("Doou 2");
            }
            else if (String.Equals(args.purchasedProduct.definition.id, kDoar3, StringComparison.Ordinal))
            {
                SalvaDoador ();
                txtBotao3.text = "Thanks!";
                MsgObrigado ("1");
                //doou 3
                Debug.LogWarning("Doou 3");
            }
            else if (String.Equals(args.purchasedProduct.definition.id, kDoar4, StringComparison.Ordinal))
            {
                SalvaDoador ();
                txtBotao4.text = "Thanks!";
                MsgObrigado ("1");  
                //doou 4
                Debug.LogWarning("Doou 4");
            }
            else if (String.Equals(args.purchasedProduct.definition.id, kDoar5, StringComparison.Ordinal))
            {
                SalvaDoador ();
                txtBotao5.text = "Thanks!";
                MsgObrigado ("1");
                //doou 5
                Debug.LogWarning("Doou 5");
            }
            else if (String.Equals(args.purchasedProduct.definition.id, kDoarTeste, StringComparison.Ordinal))
            {
                SalvaDoador ();
                txtBotao0.text = "Thanks!";
                MsgObrigado ("1");
                //doou 5
                Debug.LogWarning("Doou teste");
            }
            // Or ... an unknown product has been purchased by this user. Fill in additional products here....
            else
            {
                Debug.Log(string.Format("ProcessPurchase: FAIL. Unrecognized product: '{0}'", args.purchasedProduct.definition.id));
            }

            // Return a flag indicating whether this product has completely been received, or if the application needs
            // to be reminded of this purchase at next app launch. Use PurchaseProcessingResult.Pending when still
            // saving purchased products to the cloud, and when that save is delayed.
            return PurchaseProcessingResult.Complete;
        }

Just one more thingā€¦ After I bought my test item, I changed its localized price on Google Play for just a country. Does it affect the internal naming? I donā€™t think soā€¦ Or they shouldnā€™t. But this is not the problem, since it occurs on editor too.

I did some more tests while in editor, and this is repeated:

I go to the buying scene who have the IAP scriptā€¦ I go back to other scenes, the item is not restored.
I go to the buying scene again and click to buy another itemā€¦ I go back to my other scenes, the item is restored.

Iā€™ll try that again on my device, spending some money to myself LOL (err, 30% lost to Google). Certainly ProcessPurchase is not being called at initialization for me :frowning:

13

@Marcos-Elias_1 ,

What is the type of the product that you are trying to restore? Restoration is only supported for Non-Consumable and Subscriptions:

14

I think I found the problemā€¦ On my first tests the product was Non-Consumable, later I changed it to Consumable and it got unstable (for my account did not worked, but with other account and device it worked well). So I created a new item on Google Play with a new name and now it is working.

I was thinking that ProcessPurchase would be called on every initialization, even if the user didnā€™t buy anything, just to check item by item.

Sorry, it was my fault! (I did some tests on other devices just to confirm that everything was ok)

1 Like