consumePurchase() for recurring IAB purchases on Android

Joshua_Quick · February 5, 2013, 12:36pm

topfuncoolgames,

I see a “RESULT_SERVICE_UNAVAILABLE” twice in your log. This is a response from the Google Play app that it thinks that the network connection to Google’s servers is down. Which means that the Google Play app will be unable to send any purchase or confirm/finishTransaction requests.

I also see the following message in your log…
[lua]E/Volley (17087): [78094] BasicNetwork.performRequest: Unexpected response code 429 for https://android.clients.google.com/vending/api/ApiRequest[/lua]

HTTP status code 429 means that your Android device has sent too many requests to Google’s server and it is being blocked… which means all network requests will be blocked. This is the cause of your issue. Google is actively blocking all of your store requests.

A quick search on stackoverflow shows that other developers have ran into this as well…
http://stackoverflow.com/questions/10447801/android-in-app-billing-result-service-unavailable
http://stackoverflow.com/questions/11263733/android-iap-error-result-service-unavailable

They claim it can take up to 3 weeks (?!?) until Google stops blocking your store requests. That’s kind of crazy. This is the first I’ve heard of such an issue. Apparently this happens to developers that test Restores several times in one day, which makes sense because that means sending a confirmation request for every restored purchase.

So, it sounds like your only option is to test in-app purchases on another Android device that you haven’t tested on yet. Hopefully Google blocks by device ID and not by the app’s package name. You can also try contacting Google to lift this block, if possible. [import]uid: 32256 topic_id: 35420 reply_id: 141740[/import]

rob · January 31, 2013, 8:00pm

The only thing I can figure is that your finish isn’t getting called. Put some prints around it and make sure it’s getting called. [import]uid: 199310 topic_id: 35420 reply_id: 141139[/import]

topfuncoolgames · February 5, 2013, 6:54pm

This is what I tested last night. Yes, I also did my searched, and I am banned temporarily to restore/buy anything, but that is different story.

You can possibly said is Google’s bug. But somehow, what if I told you my other games which previously no problem, but updated recently, affected by this bug? Yes, it is affecting my other games.

Seriously none of you in Corona can reproduce this bug? Just made more than 1 purchase, and you will see.

I tried to create a new app, and is affected too. Might be Google’s problem, but no clue too. [import]uid: 143031 topic_id: 35420 reply_id: 141795[/import]

topfuncoolgames · January 31, 2013, 10:01pm

Hi Rob,

I am facing this issue too, and putting a print before and after the store.finishTransaction(...) confirmed that the function is being called.

Still this problem goes on. [import]uid: 143031 topic_id: 35420 reply_id: 141148[/import]

Joshua_Quick · February 5, 2013, 8:25pm

Can you tell me what version your Google Play app is?
The version running on most of my Android devices is 3.10.10.
You can find the version at: Settings\Apps\Google Play Store
[import]uid: 32256 topic_id: 35420 reply_id: 141802[/import]

topfuncoolgames · February 5, 2013, 8:43pm

Same as yours. 3.10.10, on both my Galaxy Nexus and Nexus 7 [import]uid: 143031 topic_id: 35420 reply_id: 141804[/import]

Dr.Klaus · January 31, 2013, 10:45pm

Rob,

Look at the following image carefully.
Could I say you about finish transaction or you know about?

All my transaction was carefully finished, shipped and money added to my account, but I continue get them in my transaction callback (and 7 successfully processed transaction get me 49 callbacks)

[import]uid: 15448 topic_id: 35420 reply_id: 141153[/import]

Joshua_Quick · February 5, 2013, 9:32pm

Hmm… and you say your older apps didn’t used to have any problems, right? When did they start having purchasing problems then?

Starting in December? (That’s when I noticed the purchase confirmation problems which we fixed.)
Or after building with the newest daily build of Corona?.. and if so does building with the older release version of Corona not have any purchasing problems (the purchases should actually fail).

Also, I’m going to contact our Corona Cloud (aka: Game Minion) developers to see if they’ve seen any issues (I haven’t heard of any). I know they’ve been actively testing Corona’s in-app purchase feature on both iOS and Android to support in-app purchase verification via the Corona Cloud servers. [import]uid: 32256 topic_id: 35420 reply_id: 141812[/import]

topfuncoolgames · February 5, 2013, 9:51pm

The time I first saw this problem IAP problem on my new game, is about 3 weeks ago. I thought is temporary Google/Corona bug. But it never get solved.
For my older game, I realize it yesterday. I updated them last week.

I try to use version 984 as suggested by one of the developer (dingo), but problem still happen. Will try version earlier than 984 and update you.

Thanks for your help, I will try to provide any information you need. [import]uid: 143031 topic_id: 35420 reply_id: 141818[/import]

Joshua_Quick · February 1, 2013, 7:22pm

Are you calling [lua]store.restore()[/lua] on application start up?
Because that’s what I’m seeing in your sample code.

If so, then that is the source of your duplicate purchase notifications.

Google Play unfortunately does not differentiate between “restored” purchases and current purchases. This means that you’ll never receive an [lua]event.transaction.state[/lua] set to “restored”.

That said, your app is expected to save the purchased item to file or database when a purchase notification has been received. So, when a restored purchase is received (which is received as a normal purchase via Google Play), then you can look up its product ID in your config file/database to recognize if it is already purchased. This is how you can recognize that it is a restored purchased.
[import]uid: 32256 topic_id: 35420 reply_id: 141289[/import]

Dr.Klaus · February 1, 2013, 10:09pm

Joshua, thank for response,

but store.restore in my example for test only (Google have no difference restore or purchase callbacks). Really, I make calls of store.purchase only.

ANY CALL OF store.purchase GET ME N*N NOTIFICATIONS (where N number of all my previous purchases). For example,

Second purchase:
1 - Callback with first Purchase
2 - Callback with second Purchase
1 - Callback with first Purchase
2 - Callback with second Purchase

3rd Purchase:
1 - Callback with first Purchase
2 - Callback with second Purchase
3 - Callback with 3rd Purchase
1 - Callback with first Purchase
2 - Callback with second Purchase
3 - Callback with 3rd Purchase
1 - Callback with first Purchase
2 - Callback with second Purchase
3 - Callback with 3rd Purchase

4 Purchase:
1
2
3
4
1
2
3
4
1
2
3
4
1
2
3
4

[import]uid: 15448 topic_id: 35420 reply_id: 141293[/import]

Joshua_Quick · February 4, 2013, 12:46pm

Hmm… I’ve never seen this behavior before. I know the [lua]store.finishTransaction()[/lua] function works, because if it didn’t, then your app would eventually receive a “cancelled” notification due to the purchase being timed out by Google Play… and you said that you’re not receiving cancelled notifications. And you’re not seeing any errors either, right?
Otherwise I’d say our CONFIRM_NOTIFICATIONS request is not getting through for some reason.

Do you see anything else in the Android log that may provide clues as to what is going wrong?
For example, log entries starting with “Finsky” comes from Google’s in-app purchase system.
I assume you are using the Android SDK tool “adb logcat” or “ddms” to view the log, and if not, give one of those tools a try since it will print log entries from all apps currently running on the device. The Google Play app is the one that is actually doing the communications, so we need to view its errors if any.

Also, can you double check that you have Android permission “com.android.vending.BILLING” set in your “build.settings” file please? You “should” get an error response if it is missing, but it doesn’t hurt to double check.
[import]uid: 32256 topic_id: 35420 reply_id: 141574[/import]

topfuncoolgames · February 5, 2013, 10:56am

Here is the logcat from my side:

[blockcode]
D/Finsky ( 1054): [1] ServerNotificationReceiver.onReceive: Handling notificationId=[CQ0dgn_a45ct]
D/Finsky ( 1054): [1] DfeNotificationManagerImpl.handleNotification: Handling notification type=[5], id=[CQ0dgn_a45ct]
D/Finsky ( 1054): [27391] MarketBillingService.getPreferredAccount: net.topfuncoolgames.barfriends: Account from first account.
D/Finsky ( 1054): [27391] MarketBillingService.getPreferredAccount: net.topfuncoolgames.barfriends: Account from first account.
D/dalvikvm( 1054): GC_CONCURRENT freed 2256K, 15% free 14919K/17380K, paused 8ms+5ms, total 122ms
D/Finsky ( 1054): [1] 2.onResponse: Notification [CQ0dgn_a45ct] successfully ack’d.
D/dalvikvm( 1398): GC_CONCURRENT freed 258K, 4% free 8956K/9240K, paused 3ms+2ms, total 20ms
D/Finsky ( 1054): [27397] PendingNotificationsService.setMarketAlarm: Setting alarm for account=v.handed@gmail.com, duration=20000
D/Finsky ( 1054): [1] MarketBillingService.sendResponseCode: Sending response RESULT_OK for request 5239820599412125809 to net.topfuncoolgames.barfriends.
D/Finsky ( 1054): [27391] MarketBillingService.getPreferredAccount: net.topfuncoolgames.barfriends: Account from first account.
D/Finsky ( 1054): [27391] MarketBillingService.getPreferredAccount: net.topfuncoolgames.barfriends: Account from first account.
D/Finsky ( 1054): [27390] MarketBillingService.getPreferredAccount: net.topfuncoolgames.barfriends: Account from first account.
D/Finsky ( 1054): [27390] MarketBillingService.getPreferredAccount: net.topfuncoolgames.barfriends: Account from first account.
…
…
…
E/Volley (17087): [78095] BasicNetwork.performRequest: Unexpected response code 429 for https://android.clients.google.com/vending/api/ApiRequest
E/Finsky (17087): [1] NotifyingErrorListener.onErrorResponse: Server error on InAppPurchaseInformationRequest: com.android.volley.ServerError
D/Finsky (17087): [1] MarketBillingService.sendResponseCode: Sending response RESULT_SERVICE_UNAVAILABLE for request 5339091311568418726 to net.topfuncoolgames.barfriends.
D/Finsky (17087): [78118] MarketBillingService.getPreferredAccount: net.topfuncoolgames.barfriends: Account from first account.
I/Corona (21661): +++++++++++++++ TRANSACTION STATE : cancelled net.topfuncoolgames.barfriends.diamond1++++++++++++++++++++++++
D/Volley (17087): [1] Request.finish: 4600 ms: [] https://android.clients.google.com/vending/api/ApiRequest NORMAL 1052 InAppPurchaseInformationRequestProto
D/dalvikvm(21661): GC_CONCURRENT freed 574K, 28% free 10115K/13940K, paused 2ms+2ms, total 18ms
D/dalvikvm(21661): WAIT_FOR_CONCURRENT_GC blocked 9ms
D/Finsky (17087): [78087] MarketBillingService.getPreferredAccount: net.topfuncoolgames.barfriends: Account from first account.
I/Corona (21661): +++++++++++++++ TRANSACTION STATE : cancelled net.topfuncoolgames.barfriends.diamond1++++++++++++++++++++++++
D/Finsky (17087): [78119] MarketBillingService.getPreferredAccount: net.topfuncoolgames.barfriends: Account from first account.
I/ActivityManager( 382): Process net.topfuncoolgames.pizzafriends (pid 23526) has died.
I/Corona (21661): +++++++++++++++ TRANSACTION STATE : cancelled net.topfuncoolgames.barfriends.diamond1++++++++++++++++++++++++
D/dalvikvm(21661): GC_CONCURRENT freed 384K, 27% free 10209K/13940K, paused 3ms+2ms, total 20ms
D/dalvikvm(21661): WAIT_FOR_CONCURRENT_GC blocked 12ms
I/Corona (21661): +++++++++++++++ TRANSACTION STATE : cancelled net.topfuncoolgames.barfriends.diamond1++++++++++++++++++++++++
I/Corona (21661): +++++++++++++++ TRANSACTION STATE : cancelled net.topfuncoolgames.barfriends.diamond1++++++++++++++++++++++++
D/dalvikvm(21661): GC_CONCURRENT freed 476K, 27% free 10210K/13940K, paused 2ms+1ms, total 26ms
D/dalvikvm(21661): WAIT_FOR_CONCURRENT_GC blocked 12ms
I/Corona (21661): +++++++++++++++ TRANSACTION STATE : cancelled net.topfuncoolgames.barfriends.diamond1++++++++++++++++++++++++
D/dalvikvm(21661): GC_CONCURRENT freed 476K, 27% free 10210K/13940K, paused 2ms+2ms, total 19ms
D/dalvikvm(21661): WAIT_FOR_CONCURRENT_GC blocked 14ms
D/Finsky (17087): [78117] MarketBillingService.getPreferredAccount: net.topfuncoolgames.barfriends: Account from first account.
I/Corona (21661): +++++++++++++++ TRANSACTION STATE : cancelled net.topfuncoolgames.barfriends.diamond1++++++++++++++++++++++++
I/Corona (21661): +++++++++++++++ TRANSACTION STATE : cancelled net.topfuncoolgames.barfriends.diamond1++++++++++++++++++++++++
D/Finsky (17087): [78088] MarketBillingService.getPreferredAccount: net.topfuncoolgames.barfriends: Account from first account.
D/dalvikvm(21661): GC_CONCURRENT freed 477K, 27% free 10210K/13940K, paused 3ms+8ms, total 34ms
D/dalvikvm(21661): WAIT_FOR_CONCURRENT_GC blocked 24ms
I/Corona (21661): +++++++++++++++ TRANSACTION STATE : cancelled net.topfuncoolgames.barfriends.diamond1++++++++++++++++++++++++
D/Finsky (17087): [78087] MarketBillingService.getPreferredAccount: net.topfuncoolgames.barfriends: Account from first account.
D/Finsky (17087): [78119] MarketBillingService.getPreferredAccount: net.topfuncoolgames.barfriends: Account from first account.
D/Finsky (17087): [78117] MarketBillingService.getPreferredAccount: net.topfuncoolgames.barfriends: Account from first account.
D/Finsky (17087): [78118] MarketBillingService.getPreferredAccount: net.topfuncoolgames.barfriends: Account from first account.
D/Finsky (17087): [78088] MarketBillingService.getPreferredAccount: net.topfuncoolgames.barfriends: Account from first account.
I/Corona (21661): +++++++++++++++ TRANSACTION STATE : cancelled net.topfuncoolgames.barfriends.diamond1++++++++++++++++++++++++
D/dalvikvm(21661): GC_CONCURRENT freed 481K, 27% free 10210K/13940K, paused 4ms+1ms, total 40ms
D/dalvikvm(21661): WAIT_FOR_CONCURRENT_GC blocked 6ms
D/Finsky (17087): [78087] MarketBillingService.getPreferredAccount: net.topfuncoolgames.barfriends: Account from first account.
I/Corona (21661): +++++++++++++++ TRANSACTION STATE : cancelled net.topfuncoolgames.barfriends.diamond1++++++++++++++++++++++++
D/dalvikvm(21661): GC_CONCURRENT freed 478K, 27% free 10209K/13940K, paused 1ms+1ms, total 18ms
D/dalvikvm(21661): WAIT_FOR_CONCURRENT_GC blocked 13ms
D/Finsky (17087): [78119] MarketBillingService.getPreferredAccount: net.topfuncoolgames.barfriends: Account from first account.
I/Corona (21661): +++++++++++++++ TRANSACTION STATE : cancelled net.topfuncoolgames.barfriends.diamond1++++++++++++++++++++++++
D/Finsky (17087): [78117] MarketBillingService.getPreferredAccount: net.topfuncoolgames.barfriends: Account from first account.
I/Corona (21661): +++++++++++++++ TRANSACTION STATE : cancelled net.topfuncoolgames.barfriends.diamond1++++++++++++++++++++++++
D/LightsService( 382): Excessive delay setting light: 67ms
D/dalvikvm(21661): GC_CONCURRENT freed 478K, 27% free 10209K/13940K, paused 3ms+2ms, total 24ms
D/dalvikvm(21661): WAIT_FOR_CONCURRENT_GC blocked 15ms
I/Corona (21661): +++++++++++++++ TRANSACTION STATE : purchased net.topfuncoolgames.barfriends.diamond1++++++++++++++++++++++++
D/Finsky (17087): [78118] MarketBillingService.getPreferredAccount: net.topfuncoolgames.barfriends: Account from first account.
I/Corona (21661): +++++++++++++++ TRANSACTION STATE : purchased net.topfuncoolgames.barfriends.diamond1++++++++++++++++++++++++
D/Finsky (17087): [78088] MarketBillingService.getPreferredAccount: net.topfuncoolgames.barfriends: Account from first account.
I/ActivityManager( 382): Start proc android.process.acore for content provider com.android.providers.contacts/.ContactsProvider2: pid=23553 uid=10000 gids={50000, 3003, 1015, 1028}
D/Finsky (17087): [78119] MarketBillingService.getPreferredAccount: net.topfuncoolgames.barfriends: Account from first account.
I/Corona (21661): +++++++++++++++ TRANSACTION STATE : cancelled net.topfuncoolgames.barfriends.diamond1++++++++++++++++++++++++
I/ActivityThread(23553): Pub com.android.voicemail: com.android.providers.contacts.VoicemailContentProvider
I/ActivityManager( 382): Start proc jp.naver.line.android for service jp.naver.line.android/.service.NaverLineService: pid=23565 uid=10067 gids={50067, 1006, 3003, 1015, 1028}
I/dalvikvm(23565): Turning on JNI app bug workarounds for target SDK version 7…
D/Finsky (17087): [78117] MarketBillingService.getPreferredAccount: net.topfuncoolgames.barfriends: Account from first account.
I/Corona (21661): +++++++++++++++ TRANSACTION STATE : cancelled net.topfuncoolgames.barfriends.diamond1++++++++++++++++++++++++
I/ActivityThread(23553): Pub com.android.contacts.dumpfile: com.android.providers.contacts.debug.DumpFileProvider
I/ActivityThread(23553): Pub applications: com.android.providers.applications.ApplicationsProvider
D/dalvikvm(21661): GC_CONCURRENT freed 482K, 27% free 10210K/13940K, paused 8ms+2ms, total 51ms
D/dalvikvm(21661): WAIT_FOR_CONCURRENT_GC blocked 9ms
D/Finsky (17087): [78118] MarketBillingService.getPreferredAccount: net.topfuncoolgames.barfriends: Account from first account.
E/Volley (17087): [78094] BasicNetwork.performRequest: Unexpected response code 429 for https://android.clients.google.com/vending/api/ApiRequest
E/Finsky (17087): [1] NotifyingErrorListener.onErrorResponse: Server error on InAppPurchaseInformationRequest: com.android.volley.ServerError
D/Finsky (17087): [1] MarketBillingService.sendResponseCode: Sending response RESULT_SERVICE_UNAVAILABLE for request 64222083666128220 to net.topfuncoolgames.barfriends.
[/blockcode]
This is not the complete one, as the complete one already too long. (about 40 * 40).

This is very easy to reproduce, just purchase 2 and more items on Android ( i tested on Galaxy Nexus and Nexus 7) [import]uid: 143031 topic_id: 35420 reply_id: 141725[/import]

Joshua_Quick · February 5, 2013, 12:36pm