Search Unity

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

Discussion in 'Unity IAP' started by Nolex, Jul 29, 2016.

Thread Status:
Not open for further replies.

  1. Nolex

    Nolex

    Joined:
    Dec 10, 2010
    Posts:
    116
    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:
    Code (CSharp):
    1. 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:

    Code (CSharp):
    1. 07-29 10:33:07.716: I/UnityIAP(13543): Unable to buy item (response: 7:Item Already Owned)
    2. 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:
    Code (CSharp):
    1.     07-28 18:30:20.114: I/UnityIAP(13921): Starting in-app billing setup.
    2.     07-28 18:30:20.122: I/UnityIAP(13921): Billing service connected.
    3.     07-28 18:30:20.123: I/UnityIAP(13921): invoking callback
    4.     07-28 18:30:20.123: I/UnityIAP(13921): Checking for in-app billing 3 support.
    5.     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]
    6.     07-28 18:30:20.127: I/UnityIAP(13921): In-app billing version 3 supported for com.game.mysupergame
    7.     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]
    8.     07-28 18:30:20.129: I/UnityIAP(13921): Subscriptions AVAILABLE.
    9.     07-28 18:30:20.130: I/UnityIAP(13921): onIabSetupFinished: 0
    10.     07-28 18:30:20.130: I/UnityIAP(13921): Requesting 4 products
    11.     07-28 18:30:20.130: I/UnityIAP(13921): QueryInventory: 4
    12.     07-28 18:30:20.131: I/UnityIAP(13921): invoking callback
    13.     07-28 18:30:20.131: I/UnityIAP(13921): Querying owned items, item type: inapp
    14.     07-28 18:30:20.131: I/UnityIAP(13921): Package name: com.game.mysupergame
    15.     07-28 18:30:20.131: I/UnityIAP(13921): Calling getPurchases with continuation token: null
    16.     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]
    17.     07-28 18:30:20.134: I/UnityIAP(13921): Owned items response: 0
    18.     07-28 18:30:20.134: I/UnityIAP(13921): Sku is owned: com.game.mysupergame_donate_pack_2
    19.     07-28 18:30:20.134: I/UnityIAP(13921): Continuation token: null
    20.     07-28 18:30:20.134: I/UnityIAP(13921): Querying SKU details.
    21.     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]
    22.     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"}
    23.     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"}
    24.     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"}
    25.     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"}
    26.     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"}
    27.     07-28 18:30:20.190: I/UnityIAP(13921): Querying owned items, item type: subs
    28.     07-28 18:30:20.190: I/UnityIAP(13921): Package name: com.game.mysupergame
    29.     07-28 18:30:20.190: I/UnityIAP(13921): Calling getPurchases with continuation token: null
    30.     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]
    31.     07-28 18:30:20.193: I/UnityIAP(13921): Owned items response: 0
    32.     07-28 18:30:20.193: I/UnityIAP(13921): Continuation token: null
    33.     07-28 18:30:20.193: I/UnityIAP(13921): Querying SKU details.
    34.     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]
    35.     07-28 18:30:20.271: I/UnityIAP(13921): onQueryInventoryFinished: true
    36.     07-28 18:30:20.271: I/UnityIAP(13921): Inventory refresh successful. (response: 0:OK)
    37.  
    38.     07-28 18:30:20.507: I/Unity(13921): OnInitialized: PASS
    39.     07-28 18:30:20.511: I/art(13921): Rejecting re-init on previously-failed class java.lang.Class<org.chromium.content.browser.FloatingWebActionModeCallback>
    40.     07-28 18:30:20.512: I/art(13921): Rejecting re-init on previously-failed class java.lang.Class<org.chromium.content.browser.FloatingWebActionModeCallback>
    41.  
    42.     07-28 18:30:20.513: I/Unity(13921): 1000 Coins , 21,99 грн., price_int21.99, iso: UAH
    43.     07-28 18:30:20.513: I/Unity(13921): Ads removing , 43,99 грн., price_int43.99, iso: UAH
    44.     07-28 18:30:20.513: I/Unity(13921): Coins double + Ads removing , 149,99 грн., price_int149.99, iso: UAH
    45.     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.
     
    Nolex, Jul 29, 2016
    #1

  2. Tarlius

    Tarlius

    Joined:
    Oct 30, 2012
    Posts:
    4
    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:

    Code (csharp):
    1.  
    2. 07-29 20:15:56.059: I/UnityIAP(12251): IAB helper created.
    3. 07-29 20:15:56.119: I/UnityIAP(12251): Starting in-app billing setup.
    4. 07-29 20:15:56.139: I/UnityIAP(12251): Billing service connected.
    5. 07-29 20:15:56.139: I/UnityIAP(12251): invoking callback
    6. 07-29 20:15:56.139: I/UnityIAP(12251): Checking for in-app billing 3 support.
    7. 07-29 20:15:56.149: I/UnityIAP(12251): In-app billing version 3 supported for jp.co.landho.purchasetest
    8. 07-29 20:15:56.149: I/UnityIAP(12251): Subscriptions AVAILABLE.
    9. 07-29 20:15:56.149: I/UnityIAP(12251): onIabSetupFinished: 0
    10. 07-29 20:15:56.149: I/UnityIAP(12251): Requesting 5 products
    11. 07-29 20:15:56.149: I/UnityIAP(12251): QueryInventory: 5
    12. 07-29 20:15:56.149: I/UnityIAP(12251): invoking callback
    13. 07-29 20:15:56.149: I/UnityIAP(12251): Querying owned items, item type: inapp
    14. 07-29 20:15:56.149: I/UnityIAP(12251): Package name: jp.co.landho.purchasetest
    15. 07-29 20:15:56.149: I/UnityIAP(12251): Calling getPurchases with continuation token: null
    16. 07-29 20:15:56.159: I/UnityIAP(12251): Owned items response: 0
    17. 07-29 20:15:56.159: I/UnityIAP(12251): Continuation token: null
    18. 07-29 20:15:56.159: I/UnityIAP(12251): Querying SKU details.
    19. 07-29 20:15:56.289: I/UnityIAP(12251): Querying owned items, item type: subs
    20. 07-29 20:15:56.289: I/UnityIAP(12251): Package name: jp.co.landho.purchasetest
    21. 07-29 20:15:56.289: I/UnityIAP(12251): Calling getPurchases with continuation token: null
    22. 07-29 20:15:56.289: I/UnityIAP(12251): Owned items response: 0
    23. 07-29 20:15:56.289: I/UnityIAP(12251): Continuation token: null
    24. 07-29 20:15:56.289: I/UnityIAP(12251): Querying SKU details.
    25. 07-29 20:15:56.429: I/UnityIAP(12251): onQueryInventoryFinished: true
    26. 07-29 20:15:56.429: I/UnityIAP(12251): Inventory refresh successful. (response: 0:OK)
    27. 07-29 20:16:42.919: I/UnityIAP(12251): onPurchaseProduct: jp.co.landho.purchasetest.money240
    28. 07-29 20:16:42.919: I/UnityIAP(12251): ITEM TYPE:inapp
    29. 07-29 20:16:43.029: I/UnityIAP(12251): invoking callback
    30. 07-29 20:16:43.029: I/UnityIAP(12251): Constructing buy intent for jp.co.landho.purchasetest.money240, item type: inapp
    31. 07-29 20:16:43.039: I/UnityIAP(12251): Launching buy intent for jp.co.landho.purchasetest.money240. Request code: 999
    32. 07-29 20:16:46.599: I/UnityIAP(12251): onActivityResult
    33. 07-29 20:16:46.599: I/UnityIAP(12251): Purchase canceled - Response: 7:Item Already Owned
    34. 07-29 20:16:46.599: I/UnityIAP(12251): onIabPurchaseFinished: false
    35. 07-29 20:16:46.599: I/UnityIAP(12251): User canceled. (response: -1005:User cancelled)
    36. 07-29 20:16:46.599: I/UnityIAP(12251): Purchase response code:-1005
    37. 07-29 20:17:17.849: I/UnityIAP(12251): onPurchaseProduct: jp.co.landho.purchasetest.money240
    38. 07-29 20:17:17.849: I/UnityIAP(12251): ITEM TYPE:inapp
    39. 07-29 20:17:17.909: I/UnityIAP(12251): invoking callback
    40. 07-29 20:17:17.909: I/UnityIAP(12251): Constructing buy intent for jp.co.landho.purchasetest.money240, item type: inapp
    41. 07-29 20:17:17.919: I/UnityIAP(12251): Launching buy intent for jp.co.landho.purchasetest.money240. Request code: 999
    42. 07-29 20:17:20.349: I/UnityIAP(12251): onActivityResult
    43. 07-29 20:17:20.349: I/UnityIAP(12251): Purchase canceled - Response: 7:Item Already Owned
    44. 07-29 20:17:20.349: I/UnityIAP(12251): onIabPurchaseFinished: false
    45. 07-29 20:17:20.349: I/UnityIAP(12251): User canceled. (response: -1005:User cancelled)
    46. 07-29 20:17:20.349: I/UnityIAP(12251): Purchase response code:-1005
    47.  
     
    Tarlius, Jul 29, 2016
    #2

  3. erika_d

    erika_d

    Joined:
    Jan 20, 2016
    Posts:
    413
    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!
     
    erika_d, Jul 29, 2016
    #3
    nicholasr likes this.

  4. Tarlius

    Tarlius

    Joined:
    Oct 30, 2012
    Posts:
    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:

    Code (csharp):
    1.  
    2. 08-01 10:55:02.039: I/UnityIAP(25582): IAB helper created.
    3. 08-01 10:55:02.089: I/UnityIAP(25582): Starting in-app billing setup.
    4. 08-01 10:55:02.109: I/UnityIAP(25582): Billing service connected.
    5. 08-01 10:55:02.109: I/UnityIAP(25582): invoking callback
    6. 08-01 10:55:02.109: I/UnityIAP(25582): Checking for in-app billing 3 support.
    7. 08-01 10:55:02.119: I/UnityIAP(25582): In-app billing version 3 supported for jp.co.landho.purchasetest
    8. 08-01 10:55:02.129: I/UnityIAP(25582): Subscriptions AVAILABLE.
    9. 08-01 10:55:02.129: I/UnityIAP(25582): onIabSetupFinished: 0
    10. 08-01 10:55:02.129: I/UnityIAP(25582): Requesting 5 products
    11. 08-01 10:55:02.129: I/UnityIAP(25582): QueryInventory: 5
    12. 08-01 10:55:02.129: I/UnityIAP(25582): invoking callback
    13. 08-01 10:55:02.129: I/UnityIAP(25582): Querying owned items, item type: inapp
    14. 08-01 10:55:02.129: I/UnityIAP(25582): Package name: jp.co.landho.purchasetest
    15. 08-01 10:55:02.129: I/UnityIAP(25582): Calling getPurchases with continuation token: null
    16. 08-01 10:55:02.139: I/UnityIAP(25582): Owned items response: 0
    17. 08-01 10:55:02.139: I/UnityIAP(25582): Continuation token: null
    18. 08-01 10:55:02.139: I/UnityIAP(25582): Querying SKU details.
    19. 08-01 10:55:02.609: I/UnityIAP(25582): Querying owned items, item type: subs
    20. 08-01 10:55:02.609: I/UnityIAP(25582): Package name: jp.co.landho.purchasetest
    21. 08-01 10:55:02.609: I/UnityIAP(25582): Calling getPurchases with continuation token: null
    22. 08-01 10:55:02.609: I/UnityIAP(25582): Owned items response: 0
    23. 08-01 10:55:02.609: I/UnityIAP(25582): Continuation token: null
    24. 08-01 10:55:02.609: I/UnityIAP(25582): Querying SKU details.
    25. 08-01 10:55:02.729: I/UnityIAP(25582): onQueryInventoryFinished: true
    26. 08-01 10:55:02.729: I/UnityIAP(25582): Inventory refresh successful. (response: 0:OK)
    27. 08-01 10:55:16.169: I/UnityIAP(25582): onPurchaseProduct: jp.co.landho.purchasetest.money240
    28. 08-01 10:55:16.169: I/UnityIAP(25582): ITEM TYPE:inapp
    29. 08-01 10:55:16.239: I/UnityIAP(25582): invoking callback
    30. 08-01 10:55:16.239: I/UnityIAP(25582): Constructing buy intent for jp.co.landho.purchasetest.money240, item type: inapp
    31. 08-01 10:55:16.239: I/UnityIAP(25582): Launching buy intent for jp.co.landho.purchasetest.money240. Request code: 999
    32. 08-01 10:55:17.969: I/UnityIAP(25582): onActivityResult
    33. 08-01 10:55:17.969: I/UnityIAP(25582): Purchase canceled - Response: 7:Item Already Owned
    34. 08-01 10:55:17.969: I/UnityIAP(25582): onIabPurchaseFinished: false
    35. 08-01 10:55:17.969: I/UnityIAP(25582): User canceled. (response: -1005:User cancelled)
    36. 08-01 10:55:17.969: I/UnityIAP(25582): Purchase response code:-1005
    37. 08-01 10:55:19.539: I/UnityIAP(25582): onPurchaseProduct: jp.co.landho.purchasetest.money240
    38. 08-01 10:55:19.539: I/UnityIAP(25582): ITEM TYPE:inapp
    39. 08-01 10:55:19.589: I/UnityIAP(25582): invoking callback
    40. 08-01 10:55:19.589: I/UnityIAP(25582): Constructing buy intent for jp.co.landho.purchasetest.money240, item type: inapp
    41. 08-01 10:55:19.599: I/UnityIAP(25582): Launching buy intent for jp.co.landho.purchasetest.money240. Request code: 999
    42. 08-01 10:55:20.899: I/UnityIAP(25582): onActivityResult
    43. 08-01 10:55:20.909: I/UnityIAP(25582): Purchase canceled - Response: 7:Item Already Owned
    44. 08-01 10:55:20.909: I/UnityIAP(25582): onIabPurchaseFinished: false
    45. 08-01 10:55:20.909: I/UnityIAP(25582): User canceled. (response: -1005:User cancelled)
    46. 08-01 10:55:20.909: I/UnityIAP(25582): Purchase response code:-1005
    47.  
    Here is the log from trying to change devices, after the first device started displaying symptoms again:

    Code (csharp):
    1.  
    2. 08-01 11:27:20.327: I/UnityIAP(26743): IAB helper created.
    3. 08-01 11:27:20.375: I/UnityIAP(26743): Starting in-app billing setup.
    4. 08-01 11:27:20.444: I/UnityIAP(26743): Billing service connected.
    5. 08-01 11:27:20.445: I/UnityIAP(26743): invoking callback
    6. 08-01 11:27:20.447: I/UnityIAP(26743): Checking for in-app billing 3 support.
    7. 08-01 11:27:20.494: I/UnityIAP(26743): In-app billing version 3 supported for jp.co.landho.purchasetest
    8. 08-01 11:27:20.497: I/UnityIAP(26743): Subscriptions AVAILABLE.
    9. 08-01 11:27:20.498: I/UnityIAP(26743): onIabSetupFinished: 0
    10. 08-01 11:27:20.498: I/UnityIAP(26743): Requesting 5 products
    11. 08-01 11:27:20.498: I/UnityIAP(26743): QueryInventory: 5
    12. 08-01 11:27:20.498: I/UnityIAP(26743): invoking callback
    13. 08-01 11:27:20.498: I/UnityIAP(26743): Querying owned items, item type: inapp
    14. 08-01 11:27:20.498: I/UnityIAP(26743): Package name: jp.co.landho.purchasetest
    15. 08-01 11:27:20.500: I/UnityIAP(26743): Calling getPurchases with continuation token: null
    16. 08-01 11:27:20.506: I/UnityIAP(26743): Owned items response: 0
    17. 08-01 11:27:20.507: I/UnityIAP(26743): Sku is owned: jp.co.landho.purchasetest.money240
    18. 08-01 11:27:20.507: I/UnityIAP(26743): Continuation token: null
    19. 08-01 11:27:20.508: I/UnityIAP(26743): Querying SKU details.
    20. 08-01 11:27:21.153: I/UnityIAP(26743): Querying owned items, item type: subs
    21. 08-01 11:27:21.153: I/UnityIAP(26743): Package name: jp.co.landho.purchasetest
    22. 08-01 11:27:21.153: I/UnityIAP(26743): Calling getPurchases with continuation token: null
    23. 08-01 11:27:21.157: I/UnityIAP(26743): Owned items response: 0
    24. 08-01 11:27:21.157: I/UnityIAP(26743): Continuation token: null
    25. 08-01 11:27:21.157: I/UnityIAP(26743): Querying SKU details.
    26. 08-01 11:27:21.357: I/UnityIAP(26743): onQueryInventoryFinished: true
    27. 08-01 11:27:21.357: I/UnityIAP(26743): Inventory refresh successful. (response: 0:OK)
    28. 08-01 11:27:21.490: I/UnityIAP(26743): Finish transaction:kggjhoekdhnmcmbgdfcgfaof.AO-J1OypOhyS-LGB6-wQ6B7e_S9e2OxUpSZ849ATFaXF9uDMC3rNJGc_4UUbrQFlu2rioN0jJ76qXGhJq4JLBVvZ1Siu1hJKP5tgQvdED1FSpMb9VHR4hEmibyg630fsWGsqQqzqvuTCvPoX36cJ59MRPtRB0ZKyOw
    29. 08-01 11:27:21.490: I/UnityIAP(26743): Consuming jp.co.landho.purchasetest.money240
    30. 08-01 11:27:21.490: I/UnityIAP(26743): invoking callback
    31. 08-01 11:27:21.490: I/UnityIAP(26743): Consuming sku: jp.co.landho.purchasetest.money240, token: kggjhoekdhnmcmbgdfcgfaof.AO-J1OypOhyS-LGB6-wQ6B7e_S9e2OxUpSZ849ATFaXF9uDMC3rNJGc_4UUbrQFlu2rioN0jJ76qXGhJq4JLBVvZ1Siu1hJKP5tgQvdED1FSpMb9VHR4hEmibyg630fsWGsqQqzqvuTCvPoX36cJ59MRPtRB0ZKyOw
    32. 08-01 11:27:22.065: I/UnityIAP(26743): Error consuming consuming sku jp.co.landho.purchasetest.money240. 8:Item not owned
    33. 08-01 11:27:22.066: I/UnityIAP(26743): onConsumeFinished:false
    34. 08-01 11:27:22.066: I/UnityIAP(26743): Error consuming sku jp.co.landho.purchasetest.money240 (response: 8:Item not owned)
    35. 08-01 11:27:22.066: I/UnityIAP(26743): 8
    36.  
    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 :/ Hopefully when the new test items are approved we can get some more info.


    Edit: Quote formatting
     
    Tarlius, Aug 1, 2016
    #4

  5. Nolex

    Nolex

    Joined:
    Dec 10, 2010
    Posts:
    116
    @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:

    Code (CSharp):
    1. 08-01 11:26:38.071: I/Unity(14585): InitializePurchasing is starting...
    2. 08-01 11:26:38.354: I/UnityIAP(14585): IAB helper created.
    3. 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
    4. 08-01 11:26:38.476: I/UnityIAP(14585): Starting in-app billing setup.
    5. 08-01 11:26:38.477: I/Unity(14585): InitializePurchasing is finish...
    6. 08-01 11:26:39.736: I/Choreographer(14585): Skipped 83 frames!  The application may be doing too much work on its main thread.
    7. 08-01 11:26:39.736: I/UnityIAP(14585): Billing service connected.
    8. 08-01 11:26:39.737: I/UnityIAP(14585): invoking callback
    9. 08-01 11:26:39.737: I/UnityIAP(14585): Checking for in-app billing 3 support.
    10. 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]
    11. 08-01 11:26:39.820: I/UnityIAP(14585): In-app billing version 3 supported for com.game.mysupergame
    12. 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]
    13. 08-01 11:26:39.822: I/UnityIAP(14585): Subscriptions AVAILABLE.
    14. 08-01 11:26:39.823: I/UnityIAP(14585): onIabSetupFinished: 0
    15. 08-01 11:26:39.823: I/UnityIAP(14585): Requesting 4 products
    16. 08-01 11:26:39.823: I/UnityIAP(14585): QueryInventory: 4
    17. 08-01 11:26:39.824: I/UnityIAP(14585): invoking callback
    18. 08-01 11:26:39.824: I/UnityIAP(14585): Querying owned items, item type: inapp
    19. 08-01 11:26:39.824: I/UnityIAP(14585): Package name: com.game.mysupergame
    20. 08-01 11:26:39.824: I/UnityIAP(14585): Calling getPurchases with continuation token: null
    21. 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]
    22. 08-01 11:26:39.890: I/UnityIAP(14585): Owned items response: 0
    23. 08-01 11:26:39.890: I/UnityIAP(14585): Sku is owned: com.game.mysupergame_donate_pack_3
    24. 08-01 11:26:39.890: I/UnityIAP(14585): Sku is owned: com.game.mysupergame_donate_pack_2
    25. 08-01 11:26:39.890: I/UnityIAP(14585): Continuation token: null
    26. 08-01 11:26:39.890: I/UnityIAP(14585): Querying SKU details.
    27. 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]
    28. 08-01 11:26:40.838: I/UnityIAP(14585): Querying owned items, item type: subs
    29. 08-01 11:26:40.838: I/UnityIAP(14585): Package name: com.game.mysupergame
    30. 08-01 11:26:40.838: I/UnityIAP(14585): Calling getPurchases with continuation token: null
    31. 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]
    32. 08-01 11:26:40.843: I/UnityIAP(14585): Owned items response: 0
    33. 08-01 11:26:40.843: I/UnityIAP(14585): Continuation token: null
    34. 08-01 11:26:40.843: I/UnityIAP(14585): Querying SKU details.
    35. 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]
    36. 08-01 11:26:40.953: D/GoogleCertificatesImpl(13090): Fetched 318 Google certificates
    37. 08-01 11:26:41.320: I/UnityIAP(14585): onQueryInventoryFinished: true
    38. 08-01 11:26:41.320: I/UnityIAP(14585): Inventory refresh successful. (response: 0:OK)
    39. 08-01 11:26:41.887: I/Unity(14585): OnInitialized: PASS
    40.  
    41. 08-01 11:26:41.894: I/Unity(14585): 1000 Coins , 21,99 грн., price_int21.99, iso: UAH, product.transactionID:
    42. 08-01 11:26:41.894: I/Unity(14585): Ads removing , 43,99 грн., price_int43.99, iso: UAH, product.transactionID: gofmjgeddgkddohFREEr@#$!@#1e551X5goGWJtYvg9gX_ldfMf9popEKH-tzwQRVMuobh0VX0TUG7JQWERQERDSAFAfdXy5k0d8yftDyvy5WuoCvFeawbPiXlEVknFTSYshD8Rfk4LUmR0zIahhcJl3FffI9zeAxDFDFj7bEHy7eYI2BEPlBQtXTmyGamXqsChFEduSH8
    43. 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
    44. 08-01 11:26:41.895: I/Unity(14585): Unlimited fuel + Coins double + Ads removing , 439,99 грн., price_int439.99, iso: UAH, product.transactionID:
    45.  
    46. 08-01 11:26:41.924: I/Unity(14585): ProcessPurchase is starting...
    47. 08-01 11:26:41.960: I/Unity(14585): ProcessPurchase: SUCCESS. Product: Remove Ads
    48. 08-01 11:26:42.007: I/UnityIAP(14585): Finish transaction:gofmjge234234hnomnmhkdi.AO-J1Ozqc1e551X5goGWJzWEr@#45X_ldfMf9popEKH-t452435Muobh0VX0TUG7J8Q2QSRx1dXy5k0d8yftDyvy5WuoCvFeawbPiXlEasdf234hD8Rfk4LUmR0zIahhcJl3FffI9zeAxbblXyrgj7bEHy7eYI2asdfsfFFErXqsChFEduSH8
    49.  
    50. 08-01 11:26:42.011: I/Unity(14585): ProcessPurchase is starting...
    51. 08-01 11:26:42.011: I/Unity(14585): ProcessPurchase: SUCCESS. Product: Coins Doubler + Remove Ads
    52. 08-01 11:26:42.015: I/UnityIAP(14585): Finish transaction:mnkgkasdafasdfngpccnbc.AO-J1Oyo3TtxfCg412Ior_uh0j68_XA4HxLauGrzjKumwW_AiTt2-Tl_J3EobB1JCCVSrlDsqThSjnO1nju3SRSzWMADEs0tryrty45654EiHfubcPXf2345fg21iaieEFdgdTPX8Pw3oemTarty42439fGjHRnKvT32ai_GY1U4
     
    Nolex, Aug 1, 2016
    #5
    erika_d likes this.

  6. Tarlius

    Tarlius

    Joined:
    Oct 30, 2012
    Posts:
    4
    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:

    Code (csharp):
    1.  
    2. 08-02 12:47:54.064: I/UnityIAP(12286): onPurchaseProduct: jp.co.landho.purchasetest.money240
    3. 08-02 12:47:54.064: I/UnityIAP(12286): ITEM TYPE:inapp
    4. 08-02 12:47:54.124: I/UnityIAP(12286): invoking callback
    5. 08-02 12:47:54.124: I/UnityIAP(12286): Constructing buy intent for jp.co.landho.purchasetest.money240, item type: inapp
    6. 08-02 12:47:54.124: I/UnityIAP(12286): Launching buy intent for jp.co.landho.purchasetest.money240. Request code: 999
    7. 08-02 12:48:00.424: I/UnityIAP(12286): onActivityResult
    8. 08-02 12:48:00.424: I/UnityIAP(12286): onIabPurchaseFinished: false
    9. 08-02 12:48:00.424: I/UnityIAP(12286): Null data in IAB result (response: -1002:Bad response received)
    10. 08-02 12:48:00.424: I/UnityIAP(12286): Purchase response code:-1002
    11.  
    12. // Broken state. Further buying returns "Already Owned"
    13. // Worked around with something like
    14. // if error is PurchaseFailureReason.Unknown Initialize()
    15. // to continue:
    16.  
    17. 08-02 12:48:00.714: I/UnityIAP(12286): Requesting 5 products
    18. 08-02 12:48:00.714: I/UnityIAP(12286): QueryInventory: 5
    19. 08-02 12:48:00.714: I/UnityIAP(12286): invoking callback
    20. 08-02 12:48:00.714: I/UnityIAP(12286): Querying owned items, item type: inapp
    21. 08-02 12:48:00.714: I/UnityIAP(12286): Package name: jp.co.landho.purchasetest
    22. 08-02 12:48:00.714: I/UnityIAP(12286): Calling getPurchases with continuation token: null
    23. 08-02 12:48:00.714: I/UnityIAP(12286): Owned items response: 0
    24. 08-02 12:48:00.714: I/UnityIAP(12286): Sku is owned: jp.co.landho.purchasetest.money240
    25. 08-02 12:48:00.714: I/UnityIAP(12286): Continuation token: null
    26. 08-02 12:48:00.714: I/UnityIAP(12286): Querying SKU details.
    27. 08-02 12:48:00.784: I/UnityIAP(12286): Querying owned items, item type: subs
    28. 08-02 12:48:00.784: I/UnityIAP(12286): Package name: jp.co.landho.purchasetest
    29. 08-02 12:48:00.784: I/UnityIAP(12286): Calling getPurchases with continuation token: null
    30. 08-02 12:48:00.784: I/UnityIAP(12286): Owned items response: 0
    31. 08-02 12:48:00.784: I/UnityIAP(12286): Continuation token: null
    32. 08-02 12:48:00.784: I/UnityIAP(12286): Querying SKU details.
    33. 08-02 12:48:00.834: I/UnityIAP(12286): onQueryInventoryFinished: true
    34. 08-02 12:48:00.834: I/UnityIAP(12286): Inventory refresh successful. (response: 0:OK)
    35. 08-02 12:48:01.204: I/UnityIAP(12286): Finish transaction:malknhahcpkadododhfhndbc.AO-J1OyPif-fHiSnzQ-iPiWLDHMhdOVkY4BH_EtakCp8x8wbIrWAdItsiVgbKK8vFb8I9o-r6ej_cjZ0bVVQ3S7t85MTo513Y05SeK8zuyDc8ktDzi30533jI6uDs8VYGut613xu8wbATU6Sx0R5TtzkNJaOYcb90Q
    36. 08-02 12:48:01.204: I/UnityIAP(12286): Consuming jp.co.landho.purchasetest.money240
    37. 08-02 12:48:01.204: I/UnityIAP(12286): invoking callback
    38. 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
    39. 08-02 12:48:01.924: I/UnityIAP(12286): Successfully consumed sku: jp.co.landho.purchasetest.money240
    40. 08-02 12:48:01.924: I/UnityIAP(12286): onConsumeFinished:true
    41. 08-02 12:48:01.924: I/UnityIAP(12286): Successful consume of sku jp.co.landho.purchasetest.money240 (response: 0:OK)
    42. 08-02 12:48:01.924: I/UnityIAP(12286): 0
    43.  
     
    Tarlius, Aug 2, 2016
    #6
    erika_d likes this.

  7. erika_d

    erika_d

    Joined:
    Jan 20, 2016
    Posts:
    413
    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.
     
    erika_d, Aug 2, 2016
    #7

  8. erika_d

    erika_d

    Joined:
    Jan 20, 2016
    Posts:
    413
    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!
     
    erika_d, Aug 3, 2016
    #8

  9. erika_d

    erika_d

    Joined:
    Jan 20, 2016
    Posts:
    413
    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?
     
    erika_d, Aug 19, 2016
    #9

  10. Tarlius

    Tarlius

    Joined:
    Oct 30, 2012
    Posts:
    4
    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! :D
     
    Tarlius, Sep 7, 2016
    #10
    erika_d likes this.

  11. onepixellab

    onepixellab

    Joined:
    Feb 29, 2016
    Posts:
    6
    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:

    Code (CSharp):
    1. 02-17 12:11:31.697 10007-10778/? I/UnityAds: com.unity3d.ads.api.Sdk.logInfo() (line:68) :: Received configuration with 2 placements
    2. 02-17 12:11:31.752 10007-10098/? I/Unity: Overriding Google AppId: 589b5d2343150f71c8ac861f
    3. 02-17 12:11:31.885 10007-10007/? D/Unity: CBPlugin: Plugin Initialized
    4. 02-17 12:11:32.104 10007-10098/? I/UnityIAP: IAB helper created.
    5. 02-17 12:11:32.244 10007-10098/? I/UnityIAP: Starting in-app billing setup.
    6. 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
    7. 02-17 12:11:32.291 10007-10007/? I/UnityIAP: Billing service connected.
    8. 02-17 12:11:32.292 10007-10810/? I/UnityIAP: invoking callback
    9. 02-17 12:11:32.292 10007-10810/? I/UnityIAP: Checking for in-app billing 3 support.
    10. 02-17 12:11:32.298 10007-10810/? I/UnityIAP: In-app billing version 3 supported for com.cowboy.horse.racing.simulator
    11. 02-17 12:11:32.303 10007-10810/? I/UnityIAP: Subscriptions AVAILABLE.
    12. 02-17 12:11:32.305 10007-10810/? I/UnityIAP: VR supported.
    13. 02-17 12:11:32.306 10007-10810/? I/UnityIAP: onIabSetupFinished: 0
    14. 02-17 12:11:32.306 10007-10810/? I/UnityIAP: Requesting 5 products
    15. 02-17 12:11:32.306 10007-10810/? I/UnityIAP: QueryInventory: 5
    16. 02-17 12:11:32.307 10007-10810/? I/UnityIAP: invoking callback
    17. 02-17 12:11:32.308 10007-10810/? I/UnityIAP: Querying owned items, item type: inapp
    18. 02-17 12:11:32.308 10007-10810/? I/UnityIAP: Package name: com.cowboy.horse.racing.simulator
    19. 02-17 12:11:32.308 10007-10810/? I/UnityIAP: Calling getPurchases with continuation token: null
    20. 02-17 12:11:32.314 10007-10810/? I/UnityIAP: Owned items response: 0
    21. 02-17 12:11:32.314 10007-10810/? I/UnityIAP: Sku is owned: com.bag.derby.horse.racing.hunt.noads
    22. 02-17 12:11:32.314 10007-10810/? I/UnityIAP: Sku is owned: com.bag.derby.horse.racing.flat
    23. 02-17 12:11:32.314 10007-10810/? I/UnityIAP: Continuation token: null
    24. 02-17 12:11:32.314 10007-10810/? I/UnityIAP: Querying SKU details.
    25. 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})
    26. 02-17 12:11:32.326 10007-10007/? D/AdsUnity: Calling loadAd() on Android
    27. 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
    28. 02-17 12:11:32.561 10007-10810/? I/UnityIAP: Querying owned items, item type: subs
    29. 02-17 12:11:32.561 10007-10810/? I/UnityIAP: Package name: com.cowboy.horse.racing.simulator
    30. 02-17 12:11:32.561 10007-10810/? I/UnityIAP: Calling getPurchases with continuation token: null
    31. 02-17 12:11:32.565 10007-10810/? I/UnityIAP: Owned items response: 0
    32. 02-17 12:11:32.565 10007-10810/? I/UnityIAP: Continuation token: null
    33. 02-17 12:11:32.565 10007-10810/? I/UnityIAP: Querying SKU details.
    34. 02-17 12:11:32.586 10007-10810/? I/UnityIAP: onQueryInventoryFinished: true
    35. 02-17 12:11:32.586 10007-10810/? I/UnityIAP: Inventory refresh successful. (response: 0:OK)
    36. 02-17 12:11:32.734 10007-10098/? I/Unity: Already recorded transaction cpiodpkdpddffgelobleekdg.AO-J1OyLRHonQ6_0DT56p-vxQ3M6zVGoVgnTFabx4Fmg0CrVcm2HOaRsYDo3X_o59iq3LOZJm6yHIEak3unNIx9XxWz_hUdX7-77qMmUImDk843oJU34JLnV6u8s8W1uPBcQMGZD6VSoMJG_3_G2JsSIqb0HwC-MrCOIW6Si97eZ9hChY37KKQ8
    37. 02-17 12:11:32.736 10007-10098/? I/UnityIAP: Finish transaction:cpiodpkdpddffgelobleekdg.AO-J1OyLRHonQ6_0DT56p-vxQ3M6zVGoVgnTFabx4Fmg0CrVcm2HOaRsYDo3X_o59iq3LOZJm6yHIEak3unNIx9XxWz_hUdX7-77qMmUImDk843oJU34JLnV6u8s8W1uPBcQMGZD6VSoMJG_3_G2JsSIqb0HwC-MrCOIW6Si97eZ9hChY37KKQ8
    38. 02-17 12:11:32.737 10007-10098/? I/Unity: Already recorded transaction imfoijoobfnnckcpomaicbod.AO-J1Owl9cA5R9iKC4HMC9YhMDEKgmQc2QSHxwDtFtdipnCbZf15FCJU6C52ItIkZsDu8Z-9q7LorG0H8Jc14CqH2v83Avs5KtwEZzmVibxBqvpCsPodmTxlxS-ELdu0H1f6Jw77FVkdCx101XuRCOtEmD6YqiS3eN2za0jhA2RLQxJfMVkptt0
    39. 02-17 12:11:32.737 10007-10098/? I/UnityIAP: Finish transaction:imfoijoobfnnckcpomaicbod.AO-J1Owl9cA5R9iKC4HMC9YhMDEKgmQc2QSHxwDtFtdipnCbZf15FCJU6C52ItIkZsDu8Z-9q7LorG0H8Jc14CqH2v83Avs5KtwEZzmVibxBqvpCsPodmTxlxS-ELdu0H1f6Jw77FVkdCx101XuRCOtEmD6YqiS3eN2za0jhA2RLQxJfMVkptt0
    40. 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
    41. 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"]]]);
    42. 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"]]]);
    43. 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"]]]);
    44. 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
    45. 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"]]]);
    46. 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
    47. 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
    48. 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
    49. 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
    50. 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
    51. 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
    52. 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
    53. 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}
    54. 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
    55. 02-17 12:13:39.359 868-905/? I/WindowManager: Gaining focus: Window{36876d35 u0 com.cowboy.horse.racing.simulator/com.unity3d.player.UnityPlayerNativeActivity}
    56. 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
    57. 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
    58. 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
    59. 02-17 12:13:44.571 10007-10098/? I/UnityIAP: isUnityVrEnabled = false
    60. 02-17 12:13:44.572 10007-10098/? I/UnityIAP: onPurchaseProduct: com.bag.derby.horse.racing.hunt.noads
    61. 02-17 12:13:44.572 10007-10098/? I/UnityIAP: ITEM TYPE:inapp
    62. 02-17 12:13:44.589 10007-10098/? I/Unity: purchase({0}): com.bag.derby.horse.racing.hunt.noads
    63. 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
    64. 02-17 12:13:44.692 10007-10007/? I/Unity Purchasing: Creating purchase activity
    65. 02-17 12:13:44.695 10007-10810/? I/UnityIAP: invoking callback
    66. 02-17 12:13:44.695 10007-10810/? I/UnityIAP: Constructing buy intent for com.bag.derby.horse.racing.hunt.noads, item type: inapp
    67. 02-17 12:13:44.725 10007-10810/? I/UnityIAP: onIabPurchaseFinished: true
    68. 02-17 12:13:44.725 10007-10810/? I/UnityIAP: Unable to buy item (response: 7:Item Already Owned)
    69. 02-17 12:13:44.725 10007-10810/? I/UnityIAP: Product purchased successfully!
    70. 02-17 12:13:44.725 10007-10810/? I/UnityIAP: NotifyUnityOfPurchase
    71. 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
    72. 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}
    73. 02-17 12:13:44.781 10007-10007/? I/UnityIAP: onActivityResult
    74. 02-17 12:13:44.796 10007-10098/? I/Unity: Already recorded transaction imfoijoobfnnckcpomaicbod.AO-J1Owl9cA5R9iKC4HMC9YhMDEKgmQc2QSHxwDtFtdipnCbZf15FCJU6C52ItIkZsDu8Z-9q7LorG0H8Jc14CqH2v83Avs5KtwEZzmVibxBqvpCsPodmTxlxS-ELdu0H1f6Jw77FVkdCx101XuRCOtEmD6YqiS3eN2za0jhA2RLQxJfMVkptt0
    75. 02-17 12:13:44.799 10007-10098/? I/UnityIAP: Finish transaction:imfoijoobfnnckcpomaicbod.AO-J1Owl9cA5R9iKC4HMC9YhMDEKgmQc2QSHxwDtFtdipnCbZf15FCJU6C52ItIkZsDu8Z-9q7LorG0H8Jc14CqH2v83Avs5KtwEZzmVibxBqvpCsPodmTxlxS-ELdu0H1f6Jw77FVkdCx101XuRCOtEmD6YqiS3eN2za0jhA2RLQxJfMVkptt0
    76. 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
    77. 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
    78. 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
    79. 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
    80. 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
    81. 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
    82. 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
    83. 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
    84.  
     
    onepixellab, Feb 17, 2017
    #11

  12. Marcos-Elias

    Marcos-Elias

    Joined:
    Nov 1, 2014
    Posts:
    159
    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.

    Code (CSharp):
    1. public PurchaseProcessingResult ProcessPurchase(PurchaseEventArgs args)
    2.         {
    3.  
    4.             PlayerPrefs.SetInt("mostrarFPS", 0);
    5.          
    6.             if (String.Equals(args.purchasedProduct.definition.id, kDoar1, StringComparison.Ordinal))
    7.             {
    8.                 SalvaDoador ();
    9.                 txtBotao1.text = "Thanks!";
    10.                 MsgObrigado ("1");
    11.                 //Doou 1
    12.                 Debug.LogWarning("Doou 1");
    13.             }
    14.             else if (String.Equals(args.purchasedProduct.definition.id, kDoar2, StringComparison.Ordinal))
    15.             {
    16.                 SalvaDoador ();
    17.                 txtBotao2.text = "Thanks!";
    18.                 MsgObrigado ("1");
    19.                 //doou 2
    20.                 Debug.LogWarning("Doou 2");
    21.             }
    22.             else if (String.Equals(args.purchasedProduct.definition.id, kDoar3, StringComparison.Ordinal))
    23.             {
    24.                 SalvaDoador ();
    25.                 txtBotao3.text = "Thanks!";
    26.                 MsgObrigado ("1");
    27.                 //doou 3
    28.                 Debug.LogWarning("Doou 3");
    29.             }
    30.             else if (String.Equals(args.purchasedProduct.definition.id, kDoar4, StringComparison.Ordinal))
    31.             {
    32.                 SalvaDoador ();
    33.                 txtBotao4.text = "Thanks!";
    34.                 MsgObrigado ("1");  
    35.                 //doou 4
    36.                 Debug.LogWarning("Doou 4");
    37.             }
    38.             else if (String.Equals(args.purchasedProduct.definition.id, kDoar5, StringComparison.Ordinal))
    39.             {
    40.                 SalvaDoador ();
    41.                 txtBotao5.text = "Thanks!";
    42.                 MsgObrigado ("1");
    43.                 //doou 5
    44.                 Debug.LogWarning("Doou 5");
    45.             }
    46.             else if (String.Equals(args.purchasedProduct.definition.id, kDoarTeste, StringComparison.Ordinal))
    47.             {
    48.                 SalvaDoador ();
    49.                 txtBotao0.text = "Thanks!";
    50.                 MsgObrigado ("1");
    51.                 //doou 5
    52.                 Debug.LogWarning("Doou teste");
    53.             }
    54.             // Or ... an unknown product has been purchased by this user. Fill in additional products here....
    55.             else
    56.             {
    57.                 Debug.Log(string.Format("ProcessPurchase: FAIL. Unrecognized product: '{0}'", args.purchasedProduct.definition.id));
    58.             }
    59.  
    60.             // Return a flag indicating whether this product has completely been received, or if the application needs
    61.             // to be reminded of this purchase at next app launch. Use PurchaseProcessingResult.Pending when still
    62.             // saving purchased products to the cloud, and when that save is delayed.
    63.             return PurchaseProcessingResult.Complete;
    64.         }
    65.  
    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 :(
     
    Marcos-Elias, Mar 5, 2017
    #12

  13. ap-unity

    ap-unity

    Unity Technologies

    Joined:
    Aug 3, 2016
    Posts:
    1,519
    ap-unity, Mar 14, 2017
    #13

  14. Marcos-Elias

    Marcos-Elias

    Joined:
    Nov 1, 2014
    Posts:
    159
    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)
     
    Marcos-Elias, Mar 18, 2017
    #14
    ap-unity likes this.
Thread Status:
Not open for further replies.