search

nbarishok / marketbilling

Automatically exported from code.google.com/p/marketbilling
0 stars 0 forks source link

Order process takes unacceptably long #19

Open GoogleCodeExporter opened 8 years ago

GoogleCodeExporter commented 8 years ago 
I'm experiencing unacceptable delays in how the orders are processed.

STEPS TO REPRODUCE:
I order an item in the market dialog that pops up. Once I click the purchase 
button and see the "Verifying purchase" progress dialog, I can see an order in 
my Checkout account about a second later. The dialog stays open for at least a 
minute and once it closes and another few seconds later I see 
onRequestPurchaseResponse being called with Now the onRequestPurchaseResponse 
RESULT_OK showing "sending purchase request" as a Toast. Then it either takes 
at least another minute or so for the onPurchaseStateChange to be called or it 
is simply never called at all!

EXPECTED OUTPUT:
All actions should happen in a maximum of like 10 seconds.

ACTUAL OUTPUT:
At least two minutes of waiting and eventual a unrecognized order.

AFFECTED ORDER IDS (IF RELEVANT):
All, i.e.: 153753506523445

OS VERSION:
Android 1.6

MARKET/MYAPPS VERSION:
"version 1002306"

DEVICE:
HTC Dream / HTC Tattoo

Original issue reported on code.google.com by NicolasG...@gmail.com on 28 Apr 2011 at 8:38

GoogleCodeExporter commented 8 years ago 
[deleted comment]
GoogleCodeExporter commented 8 years ago 
"Verifying purchase" --> "Authorizing purchase"

And as usual a "restoreTransactions" works flawlessly.

Original comment by NicolasG...@gmail.com on 28 Apr 2011 at 8:42

GoogleCodeExporter commented 8 years ago 
Same behavior is experienced using a factory-reset Nexus one with Android 2.3.3 
with Market version: 2.3.6

Note to above description, about 15 seconds after having clicked Purchase, an 
email notifying of the order is received on the buyers side.

I actually seem not to be able to get any ACTION_PURCHASE_STATE_CHANGED anymore 
at all.

Original comment by NicolasG...@gmail.com on 28 Apr 2011 at 9:14

GoogleCodeExporter commented 8 years ago 
[deleted comment]
GoogleCodeExporter commented 8 years ago 
Here is a logcat output that might be useful:

// App reinstalled and first started:
04-28 11:47:26.890: DEBUG/BillingService(1439): 
CheckBillingSupportedBillingRequest
04-28 11:47:26.890: INFO/BillingService(1439): binding to Market billing service
04-28 11:47:26.910: DEBUG/BillingService(1439): Billing service connected
04-28 11:47:26.910: DEBUG/BillingService(1439): 
CheckBillingSupportedBillingRequest
04-28 11:47:26.910: INFO/BillingService(1439): CheckBillingSupported response 
code: RESULT_OK
04-28 11:47:26.920: DEBUG/BillingService(1439): 
RestoreTransactionsBillingRequest
04-28 11:47:26.920: ERROR/BillingService(1439): restoreTransactions received 
RESULT_OK
04-28 11:47:26.920: DEBUG/BillingService(1439): request id: 237975999435368109
04-28 11:47:26.930: DEBUG/BillingService(1439): request id: -1
04-28 11:47:28.530: INFO/BillingService(1439): handleCommand() action: 
com.android.vending.billing.PURCHASE_STATE_CHANGED
04-28 11:47:28.660: INFO/BillingService(1439): handleCommand() action: 
com.android.vending.billing.RESPONSE_CODE
04-28 11:47:28.660: DEBUG/BillingService(1439): 
RestoreTransactionsBillingRequest: RESULT_OK
// Restore Transactions didn't even take 2 seconds in total!

// Trying to purchase an item:
04-28 11:53:01.960: DEBUG/BillingService(1439): RequestPurchaseBillingRequest
04-28 11:53:25.150: INFO/ActivityManager(92): Displayed 
com.android.vending/.billing.InAppBuyPageActivity: +366ms
04-28 11:53:26.130: DEBUG/vending(1068): [1] 
BaseBuyPageActivity.onPostResponse(): {PurchaseResult=OK, 
PurchaseInfo=PurchaseInfo=, SignupStatus=SIGNED_UP, TId=156736535392603, 
ShoppingCart=[ItemPrice=0,99 €, TaxInclusive=, TaxExclusive=, 
Total=0,99 €, HasTaxMessage=false, TaxMessage=null, HasFooterMessage=false, 
FooterMessage=null], RefundPolicy=Dieser In-App-Kauf kann nicht erstattet 
werden.<br/><a 
href="http://market.android.com/support/bin/answer.py?answer=1061913">Weitere 
Informationen</a><br/><a 
href="http://www.google.com/mobile/android/fsa-notification.html">Geregelt 
durch Financial Services Authority (FSA, britische Bankenaufsichtsbehörde), 
Großbritannien</a>, Instruments=[[Id=909121786242275, Name=MASTERCARD xxx-2295 
Invalid=false Type=CREDIT_CARD] [Id=124596243930288, Name=MASTERCARD xxx-2295 
Invalid=false Type=CREDIT_CARD] ], DefaultBillingInstrument=909121786242275, 
ErrorFields=[]}
04-28 11:53:26.150: DEBUG/vending(1068): [1] 
BaseBuyPageActivity.shouldAddCarrierBilling(): isProvisioned(): false 
isSavedonServer(): false radio available? true
04-28 11:53:26.150: DEBUG/vending(1068): [1] 
BaseBuyPageActivity.shouldAddCarrierBilling(): isProvisioned(): false 
isSavedonServer(): false radio available? true
04-28 11:53:34.560: DEBUG/BillingService(1439): request id: 5276085056313995557
04-28 11:53:52.040: INFO/EventLogService(243): Aggregate from 1303982631870 
(log), 1303982631870 (data)
04-28 11:54:07.600: DEBUG/vending(1068): [1] 
BaseBuyPageActivity.onOrderResponse(): state: CART_PURCHASE response: 
[PurchaseResult=OK]
04-28 11:55:06.250: WARN/ActivityManager(92): Duplicate finish request for 
HistoryRecord{406377a0 com.android.vending/.billing.InAppBuyPageActivity}
04-28 11:55:06.360: WARN/InputManagerService(92): Window already focused, 
ignoring focus gain of: 
com.android.internal.view.IInputMethodClient$Stub$Proxy@408b10f8
// "Authorizing purchase"-window stayed for ~ 1 min 30 sec!
04-28 11:55:09.560: INFO/BillingService(1439): handleCommand() action: 
com.android.vending.billing.RESPONSE_CODE
04-28 11:55:10.120: DEBUG/BillingService(1439): RequestPurchaseBillingRequest: 
RESULT_OK
// Nothing received after that!

Original comment by NicolasG...@gmail.com on 28 Apr 2011 at 10:16

GoogleCodeExporter commented 8 years ago 
I was seeing this exact issue with my application, and I'm seeing the same 
thing with Dungeons. I'm using a 2.3.3 Cyanogenmod nook color.

1) The delay after purchasing a managed item is about a minute. This logcat is 
from the Dungeons app, and com.android.vending.billing.PURCHASE_STATE_CHANGED 
never happens (for managed).

I/ActivityManager( 1008): Starting: Intent { act=android.intent.action.VIEW 
cmp=com.android.vending/.billing.InAppBuyPageActivity (has extras) } from pid -1
D/BillingService(10696): request id: 2281989857078113268
I/ActivityManager( 1008): Displayed 
com.android.vending/.billing.InAppBuyPageActivity: +506ms
D/WifiService( 1008): ACTION_BATTERY_CHANGED pluggedType: 2
W/InputManagerService( 1008): Window already focused, ignoring focus gain of: 
com.android.internal.view.IInputMethodClient$Stub$Proxy@4068ef70
I/BillingService(10696): handleCommand() action: 
com.android.vending.billing.RESPONSE_CODE
D/BillingService(10696): RequestPurchase: RESULT_OK
D/Dungeons(10696): sword_001: RESULT_OK
I/Dungeons(10696): purchase was successfully sent to server
W/InputManagerService( 1008): Window already focused, ignoring focus gain of: 
com.android.internal.view.IInputMethodClient$Stub$Proxy@40667c20
D/Dungeons(10696): buying: Potions sku: potion_001
D/BillingService(10696): RequestPurchase
I/ActivityManager( 1008): Starting: Intent { act=android.intent.action.VIEW 
cmp=com.android.vending/.billing.InAppBuyPageActivity (has extras) } from pid -1
D/BillingService(10696): request id: 2875078613916319670
I/ActivityManager( 1008): Displayed 
com.android.vending/.billing.InAppBuyPageActivity: +446ms
D/vending ( 2089): [1] BaseBuyPageActivity.onPostResponse(): 
{PurchaseResult=OK, PurchaseInfo=PurchaseInfo=, SignupStatus=SIGNED_UP, 
TId=171190352237831, ShoppingCart=[ItemPrice=US$1.50, TaxInclusive=, 
TaxExclusive=, Total=US$1.50, HasTaxMessage=false, TaxMessage=null, 
HasFooterMessage=false, FooterMessage=null], RefundPolicy=This in-app purchase 
cannot be refunded.<br/><a 
href="http://market.android.com/support/bin/answer.py?answer=1061913">More 
info</a>, Instruments=[[Id=528414885598879, Name=VISA xxx-5909 Invalid=false 
Type=CREDIT_CARD] [Id=452558018224893, Name=VISA xxx-5909 Invalid=true 
Type=CREDIT_CARD] ], DefaultBillingInstrument=528414885598879, ErrorFields=[]}
D/vending ( 2089): [1] BaseBuyPageActivity.shouldAddCarrierBilling(): 
isProvisioned(): false isSavedonServer(): false radio available? false
D/vending ( 2089): [1] BaseBuyPageActivity.shouldAddCarrierBilling(): 
isProvisioned(): false isSavedonServer(): false radio available? false
D/vending ( 2089): [1] BaseBuyPageActivity.onOrderResponse(): state: 
CART_PURCHASE response: [PurchaseResult=OK]
D/dalvikvm( 2089): GC_CONCURRENT freed 797K, 57% free 4621K/10503K, external 
1020K/1257K, paused 4ms+7ms
W/ActivityManager( 1008): Duplicate finish request for HistoryRecord{40564e98 
com.android.vending/.billing.InAppBuyPageActivity}
I/BillingReceiver(10696): notifyId: 566606267115117715

2) If I use unmanaged it seems to work fine though:

I/ActivityManager( 1008): Starting: Intent { act=android.intent.action.VIEW 
cmp=com.android.vending/.billing.InAppBuyPageActivity (has extras) } from pid -1
D/BillingService(10696): request id: 2875078613916319670
I/ActivityManager( 1008): Displayed 
com.android.vending/.billing.InAppBuyPageActivity: +446ms
D/vending ( 2089): [1] BaseBuyPageActivity.onPostResponse(): 
{PurchaseResult=OK, PurchaseInfo=PurchaseInfo=, SignupStatus=SIGNED_UP, 
TId=171190352237831, ShoppingCart=[ItemPrice=US$1.50, TaxInclusive=, 
TaxExclusive=, Total=US$1.50, HasTaxMessage=false, TaxMessage=null, 
HasFooterMessage=false, FooterMessage=null], RefundPolicy=This in-app purchase 
cannot be refunded.<br/><a 
href="http://market.android.com/support/bin/answer.py?answer=1061913">More 
info</a>, Instruments=[[Id=528414885598879, Name=VISA xxx-5909 Invalid=false 
Type=CREDIT_CARD] [Id=452558018224893, Name=VISA xxx-5909 Invalid=true 
Type=CREDIT_CARD] ], DefaultBillingInstrument=528414885598879, ErrorFields=[]}
D/vending ( 2089): [1] BaseBuyPageActivity.shouldAddCarrierBilling(): 
isProvisioned(): false isSavedonServer(): false radio available? false
D/vending ( 2089): [1] BaseBuyPageActivity.shouldAddCarrierBilling(): 
isProvisioned(): false isSavedonServer(): false radio available? false
D/vending ( 2089): [1] BaseBuyPageActivity.onOrderResponse(): state: 
CART_PURCHASE response: [PurchaseResult=OK]
D/dalvikvm( 2089): GC_CONCURRENT freed 797K, 57% free 4621K/10503K, external 
1020K/1257K, paused 4ms+7ms
W/ActivityManager( 1008): Duplicate finish request for HistoryRecord{40564e98 
com.android.vending/.billing.InAppBuyPageActivity}
I/BillingReceiver(10696): notifyId: 566606267115117715
I/BillingService(10696): handleCommand() action: 
com.example.dungeons.GET_PURCHASE_INFORMATION
D/BillingService(10696): GetPurchaseInformation
E/BillingService(10696): getPurchaseInformation received RESULT_OK
D/BillingService(10696): request id: 1477887307089998380
W/InputManagerService( 1008): Window already focused, ignoring focus gain of: 
com.android.internal.view.IInputMethodClient$Stub$Proxy@40607fc8
I/BillingService(10696): handleCommand() action: 
com.android.vending.billing.RESPONSE_CODE
D/BillingService(10696): RequestPurchase: RESULT_OK
D/Dungeons(10696): potion_001: RESULT_OK
I/Dungeons(10696): purchase was successfully sent to server
I/BillingService(10696): handleCommand() action: 
com.android.vending.billing.PURCHASE_STATE_CHANGED
I/Security(10696): signedData: 
{"nonce":-5297875013950969113,"orders":[{"notificationId":"566606267115117715","
orderId":"870232945594180","packageName":"net.jeremychase.dungeons","productId":
"potion_001","purchaseTime":1304213770000,"purchaseState":0}]}
I/Security(10696): signature: 
YK+rYh41ccPrxFYHXSnmgFA3TSoGwA14c2sREaBbYcRkLkty1dp1r+b0dSZ3N2mLXzVDJJkH/F1gu4K6
j5r/OEJKfE5FRGEz6COPP8tMQMyN8fKcv6jrxLyOo7OcDzUFtQzn1OTYuO2DjAHL+aE4DxuvhTzkZt34
9oAEGGVMrCupDdMAdnIhpr4TzK2Pz1AzQww9Lsoeo7UDi47LGXsTzrs/TVMSj7cjWm7JLNd9OLlQmK+g
bPdjmqqlkrBh7zZ48PAUduIY+CM58CGF7XZ7M8QiiIudy4TYO5SLYR1q1SJ2OMdWFHpYwkmuAHz5TM23
fH/gdGF06Qs4GXz0hmqLhg==
D/BillingService(10696): ConfirmNotifications
E/BillingService(10696): confirmNotifications received RESULT_OK
D/BillingService(10696): request id: 7166032144758808838
I/BillingService(10696): handleCommand() action: 
com.android.vending.billing.RESPONSE_CODE
D/BillingService(10696): GetPurchaseInformation: RESULT_OK
I/Dungeons(10696): onPurchaseStateChange() itemId: potion_001 PURCHASED
D/WifiService( 1008): ACTION_BATTERY_CHANGED pluggedType: 2
I/BillingService(10696): handleCommand() action: 
com.android.vending.billing.RESPONSE_CODE
D/BillingService(10696): ConfirmNotifications: RESULT_OK

Original comment by jeremych...@gmail.com on 1 May 2011 at 1:58

GoogleCodeExporter commented 8 years ago 
I payed, but got no apps, refund not possible: not happy at all! I cannot seem 
to get passed the "verifying purchase" bar, takes minutes but does not start 
downloading. I did however receive my purchase confirmation email, saying I had 
completed a transaction... 

I am on android 2.3.3 with market version 2.3.6.

PS Possibly I have to wait a little longer for the virtual creditcard to be 
fully activated...

Original comment by felixhe...@gmail.com on 1 Jun 2011 at 1:28

GoogleCodeExporter commented 8 years ago 
I'm seeing this exact same issue too (testing Dungeons on an HTC Magic running 
Android 2.2.1 and Market 2.3.6).  

Most of the time when I attempt a purchase of a managed item (the sword) it 
stays on the "Authorizing purchase ..." screen for a whole minute then returns 
to the Dungeons activity.  Under recent activity it says "sword_001: sending 
purchase request" indicating that the request has been sent to the market 
server, but the asynchronous response PURCHASE_STATE_CHANGED is never received. 

Everything works fine for unmanaged items though.  It only stays on the 
"Authorizing purchase ..." screen for about 10 seconds, and the 
PURCHASE_STATE_CHANGED response is received about a second later.

Original comment by andfa...@gmail.com on 13 Jun 2011 at 11:27

GoogleCodeExporter commented 8 years ago 
I am also experiencing the problems as stated in "Comment 8" although i am not 
using unmanaged items.

Original comment by jamesdah...@gmail.com on 14 Jun 2011 at 3:51

GoogleCodeExporter commented 8 years ago 
I'm seeing this exact issue as well.  I can purchase the same managed item over 
and over.  Checkout rings through the order but never sends an IN_APP_NOTIFY 
intent to my app so it knows the purchase went through.  The result is the 
"Authorizing Purchase" showing for a minute then vanishing and my app never 
knowing the result of the purchase.  If I attempt to restore transactions, 
checkout reports no orders even though I have many.

Original comment by st...@dogsbyte.net on 17 Jun 2011 at 8:10

GoogleCodeExporter commented 8 years ago 
I just tried the exactly same code on a Nexus One 2.3.4 with the Market 2.3.6 
and it works perfectly as long as I try to purchase the item for the first 
time. =)

But as soon as I refund it and try to purchase it again (not depending on the 
delay in between) I get the same behaviour as described above. =(

Original comment by NicolasG...@gmail.com on 18 Jun 2011 at 10:06

GoogleCodeExporter commented 8 years ago 
Same issue here!! If a purchase of a managed item was canceled (no matter which 
reason for, e.g. pressing the back button or credit card authoring 
problems...), it is not possible to complete the purchase at all! If you are in 
this state, the purchase can be made again and again (although this it 
shouldn't be able for managed items). You see them in the checkout account, but 
you never get the callback. And even restoring the database (clear data or 
reinstalling the app) does not help - you will never again receive the purchase 
state for this user and item.

What the ...? Has anybody a workaround for this?? We've got a lot of angry 
users out there and we can't even help them!!

Original comment by cl.fishl...@googlemail.com on 20 Jun 2011 at 4:27

GoogleCodeExporter commented 8 years ago 
Some more feedback on this issue would be fantastic.  It's obviously a problem. 

I've been watching this waiting for the issue to appear

https://market.android.com/support/bin/static.py?page=known_issues.cs

Original comment by st...@dogsbyte.net on 20 Jun 2011 at 4:31

GoogleCodeExporter commented 8 years ago 
I see this same problem, but notice that when I check my vendor account the 
order has been logged, but it doesn't look like the credit card has actually 
been charged yet. Is there a significant delay before the card is charged and 
the app is notified?  I cancelled the order since I'm just testing, but if I 
let it stand will my app eventually receive a notification?  Maybe in an hour?  
Maybe tomorrow?  If that's the case, it seems there should be another 
notification so we can let the user know their purchase will appear in the app 
at some time in the future.

Original comment by nstub...@gmail.com on 25 Jun 2011 at 9:41

GoogleCodeExporter commented 8 years ago 
From my testing it appears that maybe credit card verification is taking a few 
hours
purchasing does not work at the minute I added a credit card to the account, 
but it starts working a day later

Original comment by trailerp...@gmail.com on 13 Jul 2011 at 8:15

GoogleCodeExporter commented 8 years ago 
I've confirmed it with the Guys from Google - according to them "this is 
actually working as intended. The issue is that Checkout runs each buyer 
through a complex Risk engine and your card was flagged, thus, your purchase 
could not be processed. "

Google should improve their return code message so that in-app developers will 
know why a purchase is taking so long and eventually gets canceled

Original comment by skyrocki...@gmail.com on 20 Jul 2011 at 12:49

GoogleCodeExporter commented 8 years ago 
A good point that they mentioned is that a common scenario during testing will 
use multiple Google accounts with one credit card which will hit the risk 
engine 
a common user assigning one credit card to just one Google account will usually 
not hit the risk engine

Original comment by skyrocki...@gmail.com on 20 Jul 2011 at 12:57