Android store.restore() does not work. need help.

ingemar · December 19, 2012, 8:21am

OK, Google has been reset so I can purchase again.
Here’s the output from logcat while making a purchase. I have no idea what’s going on here, and why so many callbacks are being made. Something is seriously wacko somewhere…

D/Finsky ( 4695): [3725] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/Finsky ( 4695): [3725] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. I/ActivityManager( 447): START u0 {act=android.intent.action.VIEW cmp=com.android.vending/com.google.android.finsky.activities.IabActivity (has extras)} from pid -1 D/FlurryAgent( 4748): Ending session V/GCMRegistrar( 4695): Is registered on server: true D/Finsky ( 4695): [1] SelfUpdateScheduler.checkForSelfUpdate: Skipping DFE self-update. Local Version [8016010] \>= Server Version [-1] I/ActivityManager( 447): Displayed com.android.vending/com.google.android.finsky.activities.IabActivity: +92ms D/dalvikvm( 447): GC\_CONCURRENT freed 2026K, 40% free 15603K/25964K, paused 4ms+8ms, total 116ms W/Finsky ( 4695): [1] CarrierParamsAction.run: Saving carrier billing params failed. D/Finsky ( 4695): [1] GetBillingCountriesAction.run: Skip getting fresh list of billing countries. E/Finsky ( 4695): [3720] FileBasedKeyValueStore.delete: Attempt to delete 'paramsWiwTCYmaQt0G8CRLgTyneQ' failed! D/FlurryAgent( 4748): Sending report to: http://data.flurry.com/aar.do D/FlurryAgent( 4748): Report successful D/Volley ( 4695): [3704] BasicNetwork.logSlowRequests: HTTP response for request= [lifetime=9039], [size=1458], [rc=200], [retryCount=0] D/Volley ( 4695): [1] Request.finish: 9058 ms: [] https://android.clients.google.com/fdfe/completePurchase NORMAL 77 D/Finsky ( 4695): [1] ServerNotificationReceiver.onReceive: Handling notificationId=[CSe7PiCRAAxT] D/Finsky ( 4695): [1] DfeNotificationManagerImpl.handleNotification: Handling notification type=[5], id=[CSe7PiCRAAxT] D/Finsky ( 4695): [3725] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/Finsky ( 4695): [3725] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/Finsky ( 4695): [1] 2.onResponse: Notification [CSe7PiCRAAxT] successfully ackd. D/Finsky ( 4695): [1] 4.run: Applying library update: account=[afQTJXZCmS\_wqErxswXmho5DVak], corpus=3, numMutations=1 D/dalvikvm( 4748): GC\_CONCURRENT freed 337K, 57% free 8642K/19796K, paused 4ms+3ms, total 51ms D/dalvikvm( 4748): WAIT\_FOR\_CONCURRENT\_GC blocked 21ms D/Finsky ( 4695): [1] MarketBillingService.sendResponseCode: Sending response RESULT\_OK for request 2432602537296465680 to com.swipeware.freemium.bigfatgoalie. D/Finsky ( 4695): [1] PendingNotificationsService.setMarketAlarm: Setting alarm for account=ingemarbergmark@gmail.com, duration=120000 D/Finsky ( 4695): [1] 3.onMutationsApplied: App library has changed, requesting content sync. D/dalvikvm( 4748): GC\_CONCURRENT freed 458K, 57% free 8622K/19796K, paused 3ms+2ms, total 40ms D/dalvikvm( 4748): WAIT\_FOR\_CONCURRENT\_GC blocked 17ms D/dalvikvm( 4748): GC\_CONCURRENT freed 583K, 58% free 8494K/19796K, paused 3ms+3ms, total 33ms D/dalvikvm( 4748): WAIT\_FOR\_CONCURRENT\_GC blocked 26ms D/dalvikvm( 4695): GC\_CONCURRENT freed 3072K, 14% free 20280K/23504K, paused 10ms+22ms, total 121ms D/dalvikvm( 4695): WAIT\_FOR\_CONCURRENT\_GC blocked 91ms D/dalvikvm( 4748): GC\_FOR\_ALLOC freed 3K, 56% free 8779K/19796K, paused 27ms, total 27ms D/dalvikvm( 4695): WAIT\_FOR\_CONCURRENT\_GC blocked 89ms D/Finsky ( 4695): [3704] PendingNotificationsService.setMarketAlarm: Setting alarm for account=ingemarbergmark@gmail.com, duration=20000 D/dalvikvm( 4748): GC\_FOR\_ALLOC freed 594K, 58% free 8491K/19796K, paused 30ms, total 30ms I/dalvikvm-heap( 4748): Grow heap (frag case) to 8.935MB for 524304-byte allocation D/Finsky ( 4695): [1] MarketBillingService.sendResponseCode: Sending response RESULT\_OK for request 1518805495656794395 to com.swipeware.freemium.bigfatgoalie. D/dalvikvm( 4748): GC\_FOR\_ALLOC freed \<1K, 55% free 9003K/19796K, paused 28ms, total 28ms D/Finsky ( 4695): [3733] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/Finsky ( 4695): [3733] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/dalvikvm( 4748): GC\_CONCURRENT freed 2K, 55% free 9016K/19796K, paused 4ms+10ms, total 55ms D/dalvikvm( 4748): GC\_CONCURRENT freed 531K, 55% free 9014K/19796K, paused 2ms+3ms, total 35ms D/dalvikvm( 4748): WAIT\_FOR\_CONCURRENT\_GC blocked 15ms I/dalvikvm-heap( 4748): Grow heap (frag case) to 12.855MB for 4099216-byte allocation D/dalvikvm( 4748): GC\_FOR\_ALLOC freed 512K, 37% free 12504K/19796K, paused 23ms, total 23ms D/dalvikvm( 4748): GC\_CONCURRENT freed \<1K, 37% free 12504K/19796K, paused 3ms+2ms, total 24ms D/dalvikvm( 4748): GC\_FOR\_ALLOC freed \<1K, 37% free 12504K/19796K, paused 17ms, total 17ms I/dalvikvm-heap( 4748): Grow heap (frag case) to 16.264MB for 4099216-byte allocation D/dalvikvm( 4748): GC\_FOR\_ALLOC freed \<1K, 31% free 16507K/23800K, paused 25ms, total 25ms D/dalvikvm( 4748): GC\_CONCURRENT freed \<1K, 31% free 16507K/23800K, paused 3ms+3ms, total 23ms D/Finsky ( 4695): [1] MarketBillingService.sendResponseCode: Sending response RESULT\_OK for request 2527842094441314961 to com.swipeware.freemium.bigfatgoalie. D/dalvikvm( 4748): GC\_FOR\_ALLOC freed 10444K, 58% free 8502K/19796K, paused 19ms, total 19ms I/dalvikvm-heap( 4748): Grow heap (frag case) to 9.447MB for 1048592-byte allocation D/dalvikvm( 4748): GC\_FOR\_ALLOC freed \<1K, 52% free 9526K/19796K, paused 17ms, total 17ms D/dalvikvm( 4748): GC\_CONCURRENT freed 1K, 52% free 9525K/19796K, paused 3ms+2ms, total 31ms D/dalvikvm( 4748): GC\_FOR\_ALLOC freed \<1K, 52% free 9525K/19796K, paused 17ms, total 17ms I/dalvikvm-heap( 4748): Grow heap (frag case) to 10.446MB for 1048592-byte allocation D/dalvikvm( 4748): GC\_FOR\_ALLOC freed \<1K, 47% free 10549K/19796K, paused 18ms, total 18ms D/dalvikvm( 4748): GC\_CONCURRENT freed 1024K, 52% free 9526K/19796K, paused 3ms+3ms, total 25ms D/dalvikvm( 4748): GC\_CONCURRENT freed 1215K, 55% free 9013K/19796K, paused 3ms+2ms, total 21ms D/dalvikvm( 4748): GC\_CONCURRENT freed 529K, 55% free 9034K/19796K, paused 2ms+3ms, total 21ms D/dalvikvm( 4748): WAIT\_FOR\_CONCURRENT\_GC blocked 6ms D/dalvikvm( 4748): GC\_FOR\_ALLOC freed 727K, 58% free 8502K/19796K, paused 18ms, total 18ms I/dalvikvm-heap( 4748): Grow heap (frag case) to 12.356MB for 4099216-byte allocation D/dalvikvm( 4748): GC\_FOR\_ALLOC freed \<1K, 37% free 12505K/19796K, paused 17ms, total 17ms D/dalvikvm( 4748): GC\_CONCURRENT freed \<1K, 37% free 12504K/19796K, paused 2ms+2ms, total 20ms D/dalvikvm( 4748): GC\_FOR\_ALLOC freed \<1K, 37% free 12504K/19796K, paused 17ms, total 17ms I/dalvikvm-heap( 4748): Grow heap (frag case) to 16.264MB for 4099216-byte allocation D/dalvikvm( 4748): GC\_FOR\_ALLOC freed \<1K, 31% free 16507K/23800K, paused 21ms, total 21ms D/dalvikvm( 4748): GC\_CONCURRENT freed 4003K, 48% free 12504K/23800K, paused 3ms+3ms, total 23ms D/dalvikvm( 4748): GC\_FOR\_ALLOC freed 5235K, 56% free 8808K/19796K, paused 21ms, total 21ms D/dalvikvm( 4748): GC\_CONCURRENT freed 735K, 58% free 8504K/19796K, paused 3ms+3ms, total 23ms D/dalvikvm( 4748): WAIT\_FOR\_CONCURRENT\_GC blocked 12ms I/dalvikvm-heap( 4748): Grow heap (frag case) to 8.948MB for 524304-byte allocation D/dalvikvm( 4748): GC\_CONCURRENT freed 2K, 55% free 9013K/19796K, paused 3ms+2ms, total 21ms D/dalvikvm( 4748): GC\_CONCURRENT freed 528K, 55% free 9014K/19796K, paused 2ms+3ms, total 22ms D/dalvikvm( 4748): WAIT\_FOR\_CONCURRENT\_GC blocked 8ms I/dalvikvm-heap( 4748): Grow heap (frag case) to 9.946MB for 1048592-byte allocation D/dalvikvm( 4748): GC\_CONCURRENT freed 512K, 52% free 9525K/19796K, paused 3ms+2ms, total 21ms D/dalvikvm( 4748): WAIT\_FOR\_CONCURRENT\_GC blocked 18ms D/dalvikvm( 4748): GC\_FOR\_ALLOC freed \<1K, 52% free 9525K/19796K, paused 17ms, total 17ms I/dalvikvm-heap( 4748): Grow heap (frag case) to 10.446MB for 1048592-byte allocation D/dalvikvm( 4748): GC\_FOR\_ALLOC freed \<1K, 47% free 10549K/19796K, paused 25ms, total 25ms W/libc ( 4748): pthread\_create sched\_setscheduler call failed: Operation not permitted I/OpenAL\_SLES( 4748): playback\_function started D/dalvikvm( 4748): GC\_CONCURRENT freed 1046K, 52% free 9530K/19796K, paused 2ms+4ms, total 25ms D/FlurryAgent( 4748): Starting new session D/Finsky ( 4695): [3697] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/Finsky ( 4695): [3697] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. I/Corona ( 4748): Corona SDK Transaction state: cancelled I/Corona ( 4748): Corona SDK Transaction state: cancelled I/Corona ( 4748): Corona SDK Transaction state: purchased I/Corona ( 4748): Corona SDK Transaction state: cancelled I/Corona ( 4748): Corona SDK Transaction state: cancelled I/Corona ( 4748): Corona SDK Transaction state: purchased D/Finsky ( 4695): [3725] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/Finsky ( 4695): [3696] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/Finsky ( 4695): [3697] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/Finsky ( 4695): [3733] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/Finsky ( 4695): [3725] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/Finsky ( 4695): [3696] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/Finsky ( 4695): [1] MarketBillingService.sendResponseCode: Sending response RESULT\_OK for request 7417645759830704628 to com.swipeware.freemium.bigfatgoalie. I/Corona ( 4748): Corona SDK Transaction state: cancelled I/Corona ( 4748): Corona SDK Transaction state: cancelled I/Corona ( 4748): Corona SDK Transaction state: purchased D/Finsky ( 4695): [3697] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/Finsky ( 4695): [3733] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/Finsky ( 4695): [3725] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. W/InputMethodManagerService( 447): Window already focused, ignoring focus gain of: com.android.internal.view.IInputMethodClient$Stub$Proxy@42569418 attribute=null, token = android.os.BinderProxy@41c51eb0 D/Finsky ( 4695): [1] 5.onFinished: Installation state replication succeeded. [import]uid: 70847 topic_id: 29859 reply_id: 135761[/import]

dingo · December 20, 2012, 7:09am

thanks a lot for your efforts ingemar, much appreciated!

I hope it will be fixed soon, i have two games only waiting for this fix… [import]uid: 90610 topic_id: 29859 reply_id: 135888[/import]

Joshua_Quick · December 20, 2012, 11:48am

Are you two using your developer account to test in-app purchases? That is, the Google account that you are publishing your app with? If so, then that won’t work because Google Checkout will not let you buy products from yourself. Perhaps that is why your purchases are being immediately canceled.

Google recommends that you set up a test account to test in-app purchases. Have a look at their official documentation here…
http://developer.android.com/google/play/billing/billing_testing.html#billing-testing-real
[import]uid: 32256 topic_id: 29859 reply_id: 135935[/import]

ingemar · December 20, 2012, 7:52pm

@joshua
I’m fully aware that I can’t use the developer account. I only use my test account on all my android devices.

The weird thing is that I tested this when you released 2012.984, and everything was fixed in that release. I also did a logcat check at that time and everything looked OK. No multiple callbacks.
Just now I checked for a possible regression bug in the SDK by installing build 984 again and recompiling. Even with 984 I now get multiple callbacks, so it looks like something might have changed on Google’s end again.

In my three logcat dumps above I just wanted to give you the logs of what happens when I:

Restore with an active Merchant Account transaction (simulate valid user restore)
Restore with a cancelled Merchant Account transaction (simulate invalid user restore)
First time purchase

As you can see in the logs from (1) and (3) I *do* get ‘purchased’ callbacks, however they are mixed up with multiple ‘cancelled’ callbacks as well. The order in which the callbacks are given in these logs always end in a ‘purchased’ callback though. [import]uid: 70847 topic_id: 29859 reply_id: 136005[/import]

dingo · December 20, 2012, 11:41pm

@joshua: i am not using my dev account either. i always get the purchased event, but always at least one cancelled event… usually like 5. [import]uid: 90610 topic_id: 29859 reply_id: 136013[/import]

rune7 · December 19, 2012, 12:07am

Hi,

due to a customer complaints of not being able to confirm a purchase on a second device, I became aware of this recent problem in google IAP. It actually affects anyone who either re-installs an app or downloads it to more than one device.
I’ve re-built one of my apps using build 986 in order to fix this issue, but testing it on my device still returns with an error - invalidClient.
Has anyone been able to see this problem fixed in a recent build?

Also, I don’t think this is related to finishTransaction call, since we only call this method after receiving the notification from google. [import]uid: 118978 topic_id: 29859 reply_id: 135721[/import]

ingemar · December 19, 2012, 12:51am

The restore process worked for me even before build 984.

The only problem was that I got double-callbacks. First a “purchased” and then a “failed” callback before 984. This behavior started after Google updated their IAP system.
Starting with 984 I don’t get double callbacks anymore. I only get the “purchased” callback after a successful restore when testing with my test account.

[import]uid: 70847 topic_id: 29859 reply_id: 135725[/import]

rune7 · December 19, 2012, 1:15am

Perhaps this is a different issue. I never had a problem with double callbacks, but the restore used to work few months ago. I suspect the change in google IAP did something to mess with the process, since I do not get a new purchase event when trying to re-purchase, only get the fail message. [import]uid: 118978 topic_id: 29859 reply_id: 135728[/import]

ingemar · December 19, 2012, 2:03am

Ugh! Something is broken again!
I just tested with 2012.987 and I’m getting multiple callbacks on purchase.

When I purchased I got a “purchased” callback and shortly afterwards a “cancelled” callback this time instead of a “failed” callback last time I had this problem.
When I restore I also seem to get multiple callbacks but it’s not as obvious.

I need to do some more testing later and get the log from logcat to see what’s happening.

There’s definitely something going on again… *sigh* [import]uid: 70847 topic_id: 29859 reply_id: 135734[/import]

dingo · December 19, 2012, 2:08am

to keep it short and simple: i am getting charged, and then cancelled event. restore doesnt work.

joshua, *help* [import]uid: 90610 topic_id: 29859 reply_id: 135736[/import]

ingemar · December 19, 2012, 3:00am

OK, I’ve added log strings in my callback function that shows the transaction states reported by Corona SDK.
Here’s the output from the logcat when I try a restore:

D/Finsky ( 1486): [3579] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership.  
D/Finsky ( 1486): [3579] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership.  
D/Finsky ( 1486): [3586] PendingNotificationsService.setMarketAlarm: Setting alarm for account=ingemarbergmark@gmail.com, duration=20000  
D/Finsky ( 1486): [1] MarketBillingService.sendResponseCode: Sending response RESULT\_OK for request 6795394091584693651 to com.swipeware.freemium.bigfatgoalie.  
D/Finsky ( 1486): [3579] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership.  
D/Finsky ( 1486): [3579] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership.  
D/dalvikvm( 1486): GC\_CONCURRENT freed 639K, 9% free 8255K/9048K, paused 3ms+2ms, total 33ms  
I/Corona ( 1594): Corona SDK Transaction state: purchased  
D/Finsky ( 1486): [3579] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership.  
D/Finsky ( 1486): [3579] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership.  
D/Finsky ( 1486): [1] MarketBillingService.sendResponseCode: Sending response RESULT\_OK for request 4802696585570826483 to com.swipeware.freemium.bigfatgoalie.  
I/Corona ( 1594): Corona SDK Transaction state: cancelled  
I/Corona ( 1594): Corona SDK Transaction state: purchased  
D/Finsky ( 1486): [3580] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership.  
D/Finsky ( 1486): [3580] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership.  
D/Finsky ( 1486): [1] MarketBillingService.sendResponseCode: Sending response RESULT\_OK for request 8617219667100939 to com.swipeware.freemium.bigfatgoalie.  
I/Corona ( 1594): Corona SDK Transaction state: cancelled  
I/Corona ( 1594): Corona SDK Transaction state: purchased  
D/Finsky ( 1486): [3579] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership.  
D/Finsky ( 1486): [3603] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership.  
W/InputMethodManagerService( 447): Window already focused, ignoring focus gain of: com.android.internal.view.IInputMethodClient$Stub$Proxy@425d38f0 attribute=null, token = android.os.BinderProxy@4218b050

As you can see I’m now getting 5 callbacks!
purchased->cancelled->purchased->cancelled->purchased

The weird thing is the Google’s marketBillingService is only reporting RESULT_OK, although it’s reporting it multiple times which doesn’t look like a good thing…

For a new purchase I’m going to have to wait a few hours until Google resets my account so I can purchase again. [import]uid: 70847 topic_id: 29859 reply_id: 135738[/import]

ingemar · December 19, 2012, 4:29am

… and here’s the logcat from when I try to restore after I cancelled the transaction in my Google Merchant account.

D/dalvikvm( 4748): GC\_CONCURRENT freed 5633K, 57% free 8586K/19796K, paused 3ms+5ms, total 34ms  
D/Finsky ( 4695): [3725] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership.  
D/Finsky ( 4695): [3725] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership.  
I/ElegantRequestDirector( 4695): I/O exception (org.apache.http.NoHttpResponseException) caught when processing request: The target server failed to respond  
I/ElegantRequestDirector( 4695): Retrying request  
D/Finsky ( 4695): [3704] PendingNotificationsService.setMarketAlarm: Setting alarm for account=ingemarbergmark@gmail.com, duration=20000  
D/Finsky ( 4695): [1] MarketBillingService.sendResponseCode: Sending response RESULT\_OK for request 774752125873536508 to com.swipeware.freemium.bigfatgoalie.  
D/Finsky ( 4695): [3696] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership.  
D/Finsky ( 4695): [3696] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership.  
D/Finsky ( 4695): [3725] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership.  
D/Finsky ( 4695): [3725] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership.  
D/Finsky ( 4695): [1] MarketBillingService.sendResponseCode: Sending response RESULT\_OK for request 3801726047355818079 to com.swipeware.freemium.bigfatgoalie.  
I/Corona ( 4748): Corona SDK Transaction state: cancelled  
I/Corona ( 4748): Corona SDK Transaction state: cancelled  
D/Finsky ( 4695): [3697] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership.  
D/Finsky ( 4695): [3725] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership.  
D/Finsky ( 4695): [1] MarketBillingService.sendResponseCode: Sending response RESULT\_OK for request 4500032159300595469 to com.swipeware.freemium.bigfatgoalie.  
I/Corona ( 4748): Corona SDK Transaction state: cancelled  
I/Corona ( 4748): Corona SDK Transaction state: cancelled  
D/Finsky ( 4695): [3696] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership.  
D/Finsky ( 4695): [3697] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership.  
W/InputMethodManagerService( 447): Window already focused, ignoring focus gain of: com.android.internal.view.IInputMethodClient$Stub$Proxy@41f308d0 attribute=null, token = android.os.BinderProxy@4233eb98

Multiple cancelled callbacks.
Previously no callback was sent if the user tried to restore without a previous purchase.

Still waiting for the Google system to reset so I can purchase again…

I see a pattern here in that the callbacks “cancelled->cancelled” in the case above and “cancelled->purchased” are sent twice after the initial response from Google.
[import]uid: 70847 topic_id: 29859 reply_id: 135742[/import]

ingemar · December 19, 2012, 8:21am

OK, Google has been reset so I can purchase again.
Here’s the output from logcat while making a purchase. I have no idea what’s going on here, and why so many callbacks are being made. Something is seriously wacko somewhere…

D/Finsky ( 4695): [3725] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/Finsky ( 4695): [3725] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. I/ActivityManager( 447): START u0 {act=android.intent.action.VIEW cmp=com.android.vending/com.google.android.finsky.activities.IabActivity (has extras)} from pid -1 D/FlurryAgent( 4748): Ending session V/GCMRegistrar( 4695): Is registered on server: true D/Finsky ( 4695): [1] SelfUpdateScheduler.checkForSelfUpdate: Skipping DFE self-update. Local Version [8016010] \>= Server Version [-1] I/ActivityManager( 447): Displayed com.android.vending/com.google.android.finsky.activities.IabActivity: +92ms D/dalvikvm( 447): GC\_CONCURRENT freed 2026K, 40% free 15603K/25964K, paused 4ms+8ms, total 116ms W/Finsky ( 4695): [1] CarrierParamsAction.run: Saving carrier billing params failed. D/Finsky ( 4695): [1] GetBillingCountriesAction.run: Skip getting fresh list of billing countries. E/Finsky ( 4695): [3720] FileBasedKeyValueStore.delete: Attempt to delete 'paramsWiwTCYmaQt0G8CRLgTyneQ' failed! D/FlurryAgent( 4748): Sending report to: http://data.flurry.com/aar.do D/FlurryAgent( 4748): Report successful D/Volley ( 4695): [3704] BasicNetwork.logSlowRequests: HTTP response for request= [lifetime=9039], [size=1458], [rc=200], [retryCount=0] D/Volley ( 4695): [1] Request.finish: 9058 ms: [] https://android.clients.google.com/fdfe/completePurchase NORMAL 77 D/Finsky ( 4695): [1] ServerNotificationReceiver.onReceive: Handling notificationId=[CSe7PiCRAAxT] D/Finsky ( 4695): [1] DfeNotificationManagerImpl.handleNotification: Handling notification type=[5], id=[CSe7PiCRAAxT] D/Finsky ( 4695): [3725] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/Finsky ( 4695): [3725] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/Finsky ( 4695): [1] 2.onResponse: Notification [CSe7PiCRAAxT] successfully ackd. D/Finsky ( 4695): [1] 4.run: Applying library update: account=[afQTJXZCmS\_wqErxswXmho5DVak], corpus=3, numMutations=1 D/dalvikvm( 4748): GC\_CONCURRENT freed 337K, 57% free 8642K/19796K, paused 4ms+3ms, total 51ms D/dalvikvm( 4748): WAIT\_FOR\_CONCURRENT\_GC blocked 21ms D/Finsky ( 4695): [1] MarketBillingService.sendResponseCode: Sending response RESULT\_OK for request 2432602537296465680 to com.swipeware.freemium.bigfatgoalie. D/Finsky ( 4695): [1] PendingNotificationsService.setMarketAlarm: Setting alarm for account=ingemarbergmark@gmail.com, duration=120000 D/Finsky ( 4695): [1] 3.onMutationsApplied: App library has changed, requesting content sync. D/dalvikvm( 4748): GC\_CONCURRENT freed 458K, 57% free 8622K/19796K, paused 3ms+2ms, total 40ms D/dalvikvm( 4748): WAIT\_FOR\_CONCURRENT\_GC blocked 17ms D/dalvikvm( 4748): GC\_CONCURRENT freed 583K, 58% free 8494K/19796K, paused 3ms+3ms, total 33ms D/dalvikvm( 4748): WAIT\_FOR\_CONCURRENT\_GC blocked 26ms D/dalvikvm( 4695): GC\_CONCURRENT freed 3072K, 14% free 20280K/23504K, paused 10ms+22ms, total 121ms D/dalvikvm( 4695): WAIT\_FOR\_CONCURRENT\_GC blocked 91ms D/dalvikvm( 4748): GC\_FOR\_ALLOC freed 3K, 56% free 8779K/19796K, paused 27ms, total 27ms D/dalvikvm( 4695): WAIT\_FOR\_CONCURRENT\_GC blocked 89ms D/Finsky ( 4695): [3704] PendingNotificationsService.setMarketAlarm: Setting alarm for account=ingemarbergmark@gmail.com, duration=20000 D/dalvikvm( 4748): GC\_FOR\_ALLOC freed 594K, 58% free 8491K/19796K, paused 30ms, total 30ms I/dalvikvm-heap( 4748): Grow heap (frag case) to 8.935MB for 524304-byte allocation D/Finsky ( 4695): [1] MarketBillingService.sendResponseCode: Sending response RESULT\_OK for request 1518805495656794395 to com.swipeware.freemium.bigfatgoalie. D/dalvikvm( 4748): GC\_FOR\_ALLOC freed \<1K, 55% free 9003K/19796K, paused 28ms, total 28ms D/Finsky ( 4695): [3733] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/Finsky ( 4695): [3733] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/dalvikvm( 4748): GC\_CONCURRENT freed 2K, 55% free 9016K/19796K, paused 4ms+10ms, total 55ms D/dalvikvm( 4748): GC\_CONCURRENT freed 531K, 55% free 9014K/19796K, paused 2ms+3ms, total 35ms D/dalvikvm( 4748): WAIT\_FOR\_CONCURRENT\_GC blocked 15ms I/dalvikvm-heap( 4748): Grow heap (frag case) to 12.855MB for 4099216-byte allocation D/dalvikvm( 4748): GC\_FOR\_ALLOC freed 512K, 37% free 12504K/19796K, paused 23ms, total 23ms D/dalvikvm( 4748): GC\_CONCURRENT freed \<1K, 37% free 12504K/19796K, paused 3ms+2ms, total 24ms D/dalvikvm( 4748): GC\_FOR\_ALLOC freed \<1K, 37% free 12504K/19796K, paused 17ms, total 17ms I/dalvikvm-heap( 4748): Grow heap (frag case) to 16.264MB for 4099216-byte allocation D/dalvikvm( 4748): GC\_FOR\_ALLOC freed \<1K, 31% free 16507K/23800K, paused 25ms, total 25ms D/dalvikvm( 4748): GC\_CONCURRENT freed \<1K, 31% free 16507K/23800K, paused 3ms+3ms, total 23ms D/Finsky ( 4695): [1] MarketBillingService.sendResponseCode: Sending response RESULT\_OK for request 2527842094441314961 to com.swipeware.freemium.bigfatgoalie. D/dalvikvm( 4748): GC\_FOR\_ALLOC freed 10444K, 58% free 8502K/19796K, paused 19ms, total 19ms I/dalvikvm-heap( 4748): Grow heap (frag case) to 9.447MB for 1048592-byte allocation D/dalvikvm( 4748): GC\_FOR\_ALLOC freed \<1K, 52% free 9526K/19796K, paused 17ms, total 17ms D/dalvikvm( 4748): GC\_CONCURRENT freed 1K, 52% free 9525K/19796K, paused 3ms+2ms, total 31ms D/dalvikvm( 4748): GC\_FOR\_ALLOC freed \<1K, 52% free 9525K/19796K, paused 17ms, total 17ms I/dalvikvm-heap( 4748): Grow heap (frag case) to 10.446MB for 1048592-byte allocation D/dalvikvm( 4748): GC\_FOR\_ALLOC freed \<1K, 47% free 10549K/19796K, paused 18ms, total 18ms D/dalvikvm( 4748): GC\_CONCURRENT freed 1024K, 52% free 9526K/19796K, paused 3ms+3ms, total 25ms D/dalvikvm( 4748): GC\_CONCURRENT freed 1215K, 55% free 9013K/19796K, paused 3ms+2ms, total 21ms D/dalvikvm( 4748): GC\_CONCURRENT freed 529K, 55% free 9034K/19796K, paused 2ms+3ms, total 21ms D/dalvikvm( 4748): WAIT\_FOR\_CONCURRENT\_GC blocked 6ms D/dalvikvm( 4748): GC\_FOR\_ALLOC freed 727K, 58% free 8502K/19796K, paused 18ms, total 18ms I/dalvikvm-heap( 4748): Grow heap (frag case) to 12.356MB for 4099216-byte allocation D/dalvikvm( 4748): GC\_FOR\_ALLOC freed \<1K, 37% free 12505K/19796K, paused 17ms, total 17ms D/dalvikvm( 4748): GC\_CONCURRENT freed \<1K, 37% free 12504K/19796K, paused 2ms+2ms, total 20ms D/dalvikvm( 4748): GC\_FOR\_ALLOC freed \<1K, 37% free 12504K/19796K, paused 17ms, total 17ms I/dalvikvm-heap( 4748): Grow heap (frag case) to 16.264MB for 4099216-byte allocation D/dalvikvm( 4748): GC\_FOR\_ALLOC freed \<1K, 31% free 16507K/23800K, paused 21ms, total 21ms D/dalvikvm( 4748): GC\_CONCURRENT freed 4003K, 48% free 12504K/23800K, paused 3ms+3ms, total 23ms D/dalvikvm( 4748): GC\_FOR\_ALLOC freed 5235K, 56% free 8808K/19796K, paused 21ms, total 21ms D/dalvikvm( 4748): GC\_CONCURRENT freed 735K, 58% free 8504K/19796K, paused 3ms+3ms, total 23ms D/dalvikvm( 4748): WAIT\_FOR\_CONCURRENT\_GC blocked 12ms I/dalvikvm-heap( 4748): Grow heap (frag case) to 8.948MB for 524304-byte allocation D/dalvikvm( 4748): GC\_CONCURRENT freed 2K, 55% free 9013K/19796K, paused 3ms+2ms, total 21ms D/dalvikvm( 4748): GC\_CONCURRENT freed 528K, 55% free 9014K/19796K, paused 2ms+3ms, total 22ms D/dalvikvm( 4748): WAIT\_FOR\_CONCURRENT\_GC blocked 8ms I/dalvikvm-heap( 4748): Grow heap (frag case) to 9.946MB for 1048592-byte allocation D/dalvikvm( 4748): GC\_CONCURRENT freed 512K, 52% free 9525K/19796K, paused 3ms+2ms, total 21ms D/dalvikvm( 4748): WAIT\_FOR\_CONCURRENT\_GC blocked 18ms D/dalvikvm( 4748): GC\_FOR\_ALLOC freed \<1K, 52% free 9525K/19796K, paused 17ms, total 17ms I/dalvikvm-heap( 4748): Grow heap (frag case) to 10.446MB for 1048592-byte allocation D/dalvikvm( 4748): GC\_FOR\_ALLOC freed \<1K, 47% free 10549K/19796K, paused 25ms, total 25ms W/libc ( 4748): pthread\_create sched\_setscheduler call failed: Operation not permitted I/OpenAL\_SLES( 4748): playback\_function started D/dalvikvm( 4748): GC\_CONCURRENT freed 1046K, 52% free 9530K/19796K, paused 2ms+4ms, total 25ms D/FlurryAgent( 4748): Starting new session D/Finsky ( 4695): [3697] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/Finsky ( 4695): [3697] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. I/Corona ( 4748): Corona SDK Transaction state: cancelled I/Corona ( 4748): Corona SDK Transaction state: cancelled I/Corona ( 4748): Corona SDK Transaction state: purchased I/Corona ( 4748): Corona SDK Transaction state: cancelled I/Corona ( 4748): Corona SDK Transaction state: cancelled I/Corona ( 4748): Corona SDK Transaction state: purchased D/Finsky ( 4695): [3725] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/Finsky ( 4695): [3696] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/Finsky ( 4695): [3697] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/Finsky ( 4695): [3733] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/Finsky ( 4695): [3725] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/Finsky ( 4695): [3696] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/Finsky ( 4695): [1] MarketBillingService.sendResponseCode: Sending response RESULT\_OK for request 7417645759830704628 to com.swipeware.freemium.bigfatgoalie. I/Corona ( 4748): Corona SDK Transaction state: cancelled I/Corona ( 4748): Corona SDK Transaction state: cancelled I/Corona ( 4748): Corona SDK Transaction state: purchased D/Finsky ( 4695): [3697] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/Finsky ( 4695): [3733] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. D/Finsky ( 4695): [3725] MarketBillingService.getPreferredAccount: com.swipeware.freemium.bigfatgoalie: Account determined from library ownership. W/InputMethodManagerService( 447): Window already focused, ignoring focus gain of: com.android.internal.view.IInputMethodClient$Stub$Proxy@42569418 attribute=null, token = android.os.BinderProxy@41c51eb0 D/Finsky ( 4695): [1] 5.onFinished: Installation state replication succeeded. [import]uid: 70847 topic_id: 29859 reply_id: 135761[/import]

dingo · December 20, 2012, 7:09am

thanks a lot for your efforts ingemar, much appreciated!

I hope it will be fixed soon, i have two games only waiting for this fix… [import]uid: 90610 topic_id: 29859 reply_id: 135888[/import]

Joshua_Quick · December 20, 2012, 11:48am

Are you two using your developer account to test in-app purchases? That is, the Google account that you are publishing your app with? If so, then that won’t work because Google Checkout will not let you buy products from yourself. Perhaps that is why your purchases are being immediately canceled.

Google recommends that you set up a test account to test in-app purchases. Have a look at their official documentation here…
http://developer.android.com/google/play/billing/billing_testing.html#billing-testing-real
[import]uid: 32256 topic_id: 29859 reply_id: 135935[/import]

ingemar · December 20, 2012, 7:52pm

@joshua
I’m fully aware that I can’t use the developer account. I only use my test account on all my android devices.

The weird thing is that I tested this when you released 2012.984, and everything was fixed in that release. I also did a logcat check at that time and everything looked OK. No multiple callbacks.
Just now I checked for a possible regression bug in the SDK by installing build 984 again and recompiling. Even with 984 I now get multiple callbacks, so it looks like something might have changed on Google’s end again.

In my three logcat dumps above I just wanted to give you the logs of what happens when I:

Restore with an active Merchant Account transaction (simulate valid user restore)
Restore with a cancelled Merchant Account transaction (simulate invalid user restore)
First time purchase

As you can see in the logs from (1) and (3) I *do* get ‘purchased’ callbacks, however they are mixed up with multiple ‘cancelled’ callbacks as well. The order in which the callbacks are given in these logs always end in a ‘purchased’ callback though. [import]uid: 70847 topic_id: 29859 reply_id: 136005[/import]

dingo · December 20, 2012, 11:41pm

@joshua: i am not using my dev account either. i always get the purchased event, but always at least one cancelled event… usually like 5. [import]uid: 90610 topic_id: 29859 reply_id: 136013[/import]

Joshua_Quick · December 27, 2012, 12:17pm

ingemar, dingo,

Sorry about the late response.

So far, I’m only hearing about this canceled purchase issue from you two. I’m wondering if your test accounts have been wrongly flagged by Google as fraudulent. Have you tried contacting Google about this? I say this, because I’m not sure what we can on our end to resolve this since Corona merely passes the notifications received from Google to your app.

There are other Android developers who have filed similar issues with Google, as can be seen in the link below. So, I’m thinking this is really a system issue on Google’s end.
http://code.google.com/p/marketbilling/issues/detail?id=14#c28

I suppose one way to prove that it’s an account issue would be to set up another test account and see if that account can successfully make purchases.

I also recommend that you start a new forum thread about this issue to see if there are other Corona developers who are running into the same issue. Especially since the title of this forum thread is now unrelated. Who knows, perhaps other Corona developers have resolved this issue before and may be able to help you with this.

I hope this helps. I’m not trying to blow you off here. I’m just not sure what else to recommend at the moment. We’re fighting a black box and we just don’t know why Google’s in-app purchase system isn’t cooperating with you two. [import]uid: 32256 topic_id: 29859 reply_id: 136485[/import]

ingemar · December 28, 2012, 6:36am

I had the same idea, so I created a new test user, but with no difference.

IAP on Android is flaky to say the least. I took the Corona IAP demo app, compiled with 994, and even that it isn’t behaving 100%. I would say that 1 of 20 purchase attempts return an “invalid client” response (although never a multiple callback).

I’m still doing some testing to see if I can get to the bottom of this. When I have more info I’ll open up a new thread instead of continuing to hijack this one… [import]uid: 70847 topic_id: 29859 reply_id: 136582[/import]

Joshua_Quick · December 28, 2012, 11:44am

I suspect that the INVALID_CLIENT error that you are getting 1 out of 20 times with the sample app is due to a connectivity issue. That error will happen if you do not have Internet access or if Google Play is not set up with a valid account that can make purchases or if anything is wrong with Google Play. For your customers, odds are Google Play is set up correctly (because how else are they going to download your app?) so it is most likely an Internet access issue. Well, it could also mean that your customer might have misconfigured their payment settings too.

I saw a “Target server failed to respond” error in the log that you posted. That error is coming from the Google Play app. In that case, you shouldn’t be able to make a purchase… and yet you were able to and it was quickly canceled. This is very strange indeed. [import]uid: 32256 topic_id: 29859 reply_id: 136618[/import]