search

j3k0 / cordova-plugin-purchase

In-App Purchase for Cordova on iOS, Android and Windows
https://purchase.cordova.fovea.cc
1.29k stars 535 forks source link

Verify for subscriptions being called twice...is this a problem? #225

Closed rwillett closed 9 years ago

rwillett commented 9 years ago

Hi,

We're still working our way through purchasing non-auto renewing subscriptions and as we sort out one issue, another one pops up.

We've noticed that the product.verify() function is being called twice which means that the web server that validates the verification is called twice.

if we log the first validation on the web server 

HandlePostCheckPurchase;
id: 'Dummy_One_Week_Subscription_10002'
type: paid subscription
state: approved
canPurchase: false (0)
alias: 'Weekly non renewing subscription'
valid: true (1)
owned: false (0)
loaded: true (1)
transactionId: 160515194
*******
    [1] product_id: Dummy_One_Week_Subscription_10002 transaction_id: 160494816 purchase_date: 2015-06-23 14:02:19 Etc/GMT
    [2] product_id: Dummy_One_Week_Subscription_10002 transaction_id: 160514399 purchase_date: 2015-06-23 16:47:46 Etc/GMT
*******

Returning $VAR1 = {
          'ok' => 0,
          'timestamp' => '2015-06-23 17:56:32',
          'data' => {
                      'error' => {
                                   'message' => 'Expired'
                                 },
                      'code' => 6778003
                    }
        };

We can see that the verification has a transaction_id, 160515194, attached to it. However when we send the app store receipt to Apple to be verified we get back a valid app store receipt But the transaction, 160515194, is NOT in the json_response that Apple returns.

The web server sends back an expired response (thats the $VAR1 variable above) as we have no record of the transaction from Apple which is correct. We then get a second verification around three seconds later appear on the validation server, its never quicker than that and we haven't done anything manually, this is happening the background on the app in the purchase plugin.

2015-06-23 17:56:35
Epoch: 1435078595

HandlePostCheckPurchase;
id: 'Dummy_One_Week_Subscription_10002'
type: paid subscription
state: approved
canPurchase: false (0)
alias: 'Weekly non renewing subscription'
valid: true (1)
owned: false (0)
loaded: true (1)
transactionId: 160515194
*******
    [1] product_id: Dummy_One_Week_Subscription_10002 transaction_id: 160494816 purchase_date: 2015-06-23 14:02:19 Etc/GMT
    [2] product_id: Dummy_One_Week_Subscription_10002 transaction_id: 160514399 purchase_date: 2015-06-23 16:47:46 Etc/GMT
    [3] product_id: Dummy_One_Week_Subscription_10002 transaction_id: 160515194 purchase_date: 2015-06-23 16:56:28 Etc/GMT
*******

CheckTransactionIsValidAndHasNotExpired: Dummy_One_Week_Subscription_10002 160515194 173
Returning $VAR1 = {
          'timestamp' => '2015-06-23 17:56:35',
          'data' => {},
          'ok' => 1
        };

-----------------------------------------

We can see that the verification STILL has the transaction_id, 160515194, attached to it. However when we send the app store receipt to Apple to be verified we get back a valid app store receipt but this time the transaction, 160515194, IS in the json_response. We can see this in the list of receipts between the *** lines. (We've cut down some of the number of the transaction_id for readability, that are all too big and confuse our tired eyes).

So this time we send back the OK value in our JSON back to the application.

This looks wrong to us, we would have thought that the app store receipt in the first verification would include the transaction 160515194 in it so that the validating web server would return OK. The transaction_id, 160515194, is correct as it is found and validated in the second verification. Since we do not create the transaction_id, something appears to be wrong.

Why would we have the correct transaction_id BUT the App Store Receipt not contain it until the second call to the validation server.

Is this even a problem apart from making two calls rather than one to the validation server? We've gone through the code yet again and we only call product.verify() from one place

            store.when(possibleProducts[i].id).approved(function(product) {
                // ConsoleLog("Approved: Now verify subscription");
                StoreProductPrint("Store: Approved" , product);

                product.verify().success(function (product , purchaseData) {
                    ConsoleLog("\t\t**** Success " + JSON.stringify(purchaseData));
                }).expired(function(product) {
                    ConsoleLog("\t\t**** Expired " + JSON.stringify(product));
                });
            });

We've added product.verify.success() and product.verify.expired() to try and dig in to the detail.

The problem appears to be calling the validator with what we think is the wrong app store receipt but we don't what causes that.

Any suggestions or help welcomed.

Thanks,

Rob

Alphatiger commented 9 years ago

222 and #223 , always the store is giving approved status on app launch irrespective of your verification and product finish abalablalbal.

So saved the order id in db and in approved status trigger compare if a new orderid(different order id) is there from store and then do a custom verfification and process, else if they are same ignore.

rwillett commented 9 years ago

Thanks for taking the time to reply, I've read through #222 and can see that this is an Android issue, mine is just with the Apple Store. I've not dived down the Android store yet.

I've just closed down the iPhone app and restarted. My subscription has gone from owned == TRUE to owned == false as I would expect. So I think the behaviour on iOS looks different.

My issue is still that I am getting multiple verification requests being sent to the validation server. As an example, simply closing down the app, and restarting it to check if Alphatigers behaviour on Android is the same on iOS, I got six verification requests! I hadn't brought anything new, I just let the app start up and called store.refresh().

I'm going to keep looking to see if we can see why we have this many requests which seems silly to me.

Rob

Alphatiger commented 9 years ago

Thanks for the info, i am starting with ios now, this will be helpfull for me for your multiple requests check if you are registering multiple times.

rwillett commented 9 years ago

Already checked for multiple registrations.

Also checked to see if I had initialised the store twice by mistake.

One thing I have found is that I have store.refresh() in the store.ready() function and immediately at the end of my function to initialise the store. I appear to be calling store.refresh twice very quickly one after the other and I think this is a problem. Removed the store.refresh from the store.ready callback seems to reduce the number of calls from six down to three, which is two too many though.

I'll keep looking through the code to try and work out why there are so many calls.

I'm still unclear as to if this is a problem or not though.

Rob

rwillett commented 9 years ago

I think I can see what the problem is, I'm not sure I understand it but I can see something.

I've turned on the DEBUG flag which I normally don't use as the output is simply too much and I can't work like that.

It appears, and I hope Jean will jump in and correct me here, that the Storekit is making three calls to the validation server when the first call to the validation server returns expired.

I'll cut and paste the relevant sections to try and illustrate the point.

Background

I have created and purchased a non-renewing subscription. This has a transaction ID of 160539002.

When I call store.refresh() to update the status of all the products, a debug line in the Xcode console shows

2015-06-23 22:44:05.072 Jambuster[11684:1832436] InAppPurchase[js]: refreshing appStoreReceipt
2015-06-23 22:44:05.073 Jambuster[11684:1832436] InAppPurchase[objc]: Request to refresh app receipt
2015-06-23 22:44:05.074 Jambuster[11684:1832436] InAppPurchase[objc]: Starting receipt refresh request...
2015-06-23 22:44:05.075 Jambuster[11684:1832436] InAppPurchase[objc]: Receipt refresh request started
2015-06-23 22:44:06.068 Jambuster[11684:1832436] InAppPurchase[js]: appStoreReceipt already loaded:
2015-06-23 22:44:06.070 Jambuster[11684:1832436] InAppPurchase[js]: MIIdvQYJKoZIhvcNAQcCoIIdrjCCHaoCAQExCzAJBgUrDgMCGgUAMIINbgYJKoZIhvcN........

This is sent to my validation server at 22:44:05, here's the output. I only display the first and last 20 characters of the App Store Receipt, but I also convert the receipt to an sha1 version which is far easier to understand and follow. I have checked the first 20 and last 20 characters against the App Store Receipt in Xcode and they are the same. 

2015-06-23 22:44:05
Epoch: 1435095845

HandlePostCheckPurchase;
id: 'Dummy_One_Week_Subscription_10002'
type: paid subscription
state: approved
canPurchase: false (0)
alias: 'Weekly non renewing subscription'
valid: true (1)
owned: true (1)
loaded: true (1)
appStoreReceipt: MIIdvQYJKoZIhvcNAQcC...QEe2KGuVxXD7gyUHkjyP
appStoreReceipt_sha1: 9b2a36fd25a5a7e9c4c15b946977a0830c35b098
transactionId: N/A
*******
    [1] product_id: Dummy_One_Week_Subscription_10002 transaction_id: 160539002 purchase_date: 2015-06-23 21:39:41 Etc/GMT
*******

Returning $VAR1 = {
          'data' => {
                      'error' => {
                                   'message' => 'Expired'
                                 },
                      'code' => 6778003
                    },
          'timestamp' => '2015-06-23 22:44:05',
          'ok' => 0
        };

This is correct as the subscription has expired. So far so good....

BUT

The app then makes another call approx two seconds later, this is something in the plugin or StoreKit code. I do not have code to make this call.

2015-06-23 22:44:08.611 Jambuster[11684:1832436] [store.js] DEBUG: verify -> error: {"error":{"message":"Expired"},"code":6778003}
2015-06-23 22:44:08.612 Jambuster[11684:1832436] InAppPurchase[js]: refreshing appStoreReceipt
2015-06-23 22:44:08.613 Jambuster[11684:1832436] InAppPurchase[objc]: Request to refresh app receipt
2015-06-23 22:44:08.614 Jambuster[11684:1832436] InAppPurchase[objc]: Starting receipt refresh request...
2015-06-23 22:44:08.615 Jambuster[11684:1832436] InAppPurchase[objc]: Receipt refresh request started
2015-06-23 22:44:09.168 Jambuster[11684:1832436] InAppPurchase[objc]: Got refreshed receipt
2015-06-23 22:44:09.172 Jambuster[11684:1832436] InAppPurchase[objc]: Send new receipt data
2015-06-23 22:44:09.177 Jambuster[11684:1832436] InAppPurchase[js]: infoPlist: london.jambuster.client10000,0.1.1,1146880,????
2015-06-23 22:44:09.493 Jambuster[11684:1832436] InAppPurchase[js]: appStoreReceipt already loaded:
2015-06-23 22:44:09.494 Jambuster[11684:1832436] InAppPurchase[js]: MIId0gYJKoZIhvcNAQcCoIIdwzCCHb8CAQExCzAJBgUrDgMCGgUAMIINgwYJK........

Note the lines Starting receipt refresh request..., Got refreshed receipt and that the start of the App Store Receipt is not the same. A new receipt has been generated from the Sandbox.

The output from the web server is now

2015-06-23 22:44:08
Epoch: 1435095848

HandlePostCheckPurchase;
id: 'Dummy_One_Week_Subscription_10002'
type: paid subscription
state: approved
canPurchase: false (0)
alias: 'Weekly non renewing subscription'
valid: true (1)
owned: true (1)
loaded: true (1)
appStoreReceipt: MIId0gYJKoZIhvcNAQcC...JjA0546sByXUagUPqpT8
appStoreReceipt_sha1: 51b162a782a8225cb6114243836fc1ba6d3ad767
transactionId: N/A
*******
    [1] product_id: Dummy_One_Week_Subscription_10002 transaction_id: 160539002 purchase_date: 2015-06-23 21:39:41 Etc/GMT
*******

Returning $VAR1 = {
          'data' => {
                      'code' => 6778003,
                      'error' => {
                                   'message' => 'Expired'
                                 }
                    },
          'timestamp' => '2015-06-23 22:44:08',
          'ok' => 0
        };

The App Store Receipt sent has changed. We can see this in the first few characters of the App Store Receipt but its easier to see that the sha1 representation has completely changed. It was 9b2a36fd25a5a7e9c4c15b946977a0830c35b098 and is now 51b162a782a8225cb6114243836fc1ba6d3ad767

So we have a newly generated App Store Receipt being sent.

However this is not the end of it, we get a 3rd crack to verify it.

2015-06-23 22:44:11.468 Jambuster[11684:1832436] [store.js] DEBUG: verify -> 0
2015-06-23 22:44:11.469 Jambuster[11684:1832436] [store.js] DEBUG: verify -> error: {"code":6778003,"error":{"message":"Expired"}}
2015-06-23 22:44:11.470 Jambuster[11684:1832436] InAppPurchase[js]: refreshing appStoreReceipt
2015-06-23 22:44:11.470 Jambuster[11684:1832436] InAppPurchase[objc]: Request to refresh app receipt
2015-06-23 22:44:11.471 Jambuster[11684:1832436] InAppPurchase[objc]: Starting receipt refresh request...
2015-06-23 22:44:11.472 Jambuster[11684:1832436] InAppPurchase[objc]: Receipt refresh request started
2015-06-23 22:44:12.196 Jambuster[11684:1832436] InAppPurchase[objc]: Got refreshed receipt
2015-06-23 22:44:12.199 Jambuster[11684:1832436] InAppPurchase[objc]: Send new receipt data
2015-06-23 22:44:12.204 Jambuster[11684:1832436] InAppPurchase[js]: infoPlist: london.jambuster.client10000,0.1.1,1146880,????
2015-06-23 22:44:12.515 Jambuster[11684:1832436] InAppPurchase[js]: appStoreReceipt already loaded:
2015-06-23 22:44:12.517 Jambuster[11684:1832436] InAppPurchase[js]: MIIdwwYJKoZIhvcNAQcCoIIdtDCC

As before there is a new App Store Receipt from the Sandbox.

We can see the Web server validate this (or rather expire it)

2015-06-23 22:44:11
Epoch: 1435095851

HandlePostCheckPurchase;
id: 'Dummy_One_Week_Subscription_10002'
type: paid subscription
state: approved
canPurchase: false (0)
alias: 'Weekly non renewing subscription'
valid: true (1)
owned: true (1)
loaded: true (1)
appStoreReceipt: MIIdwwYJKoZIhvcNAQcC...q92BLkPHQ0FY1rGyZXJk
appStoreReceipt_sha1: f8d4a307c0c98fc2325a24177f89b2e082754145
transactionId: N/A
*******
    [1] product_id: Dummy_One_Week_Subscription_10002 transaction_id: 160539002 purchase_date: 2015-06-23 21:39:41 Etc/GMT
*******

Returning $VAR1 = {
          'ok' => 0,
          'data' => {
                      'code' => 6778003,
                      'error' => {
                                   'message' => 'Expired'
                                 }
                    },
          'timestamp' => '2015-06-23 22:44:11'
        };

The sha1 has changed again which is what we would expect as we can see that the App Store Receipt has changed yet again.

So the debugging shows that three different App Store Receipts are used and generated. I believe one of them is from a cache and the other two are actually generated. This is based on reading the debug messages.

These App Store Receipts are valid as I check them against the Apple Sandbox Receipt server.

So I can see why I get three verifications in my validation server BUT I do not know why the StoreKit does this or even if it is a problem.

All suggestions and ideas welcomed.

Rob

rwillett commented 9 years ago

I think I now understand what the Storekit/plugin is doing.

Its actually making three calls to the verification server.

  1. The first call has no new transaction id and all the old purchase data.
  2. The second call has the new transaction id and all the old purchase data.
  3. The third call has the new transaction_id and all the old purchase data PLUS the new transaction id.

I think this is a way of verifying that the old transactions are expired (1), that there is no transaction with the new transaction id (2) and that the new transaction id is valid (3).

I'm closing this as

a) no one seems that bothered about it :) it might be useful for somebody though.

and

b) I can see some sort of logic here.

Rob

mikehayesuk commented 8 years ago

It sounds like your issue may be a bit more complicated, however I'm going to write this here anyway incase anybody is searching (like myself) to find out why the validator is being called multiple times during configuration.

As I suspected, the validator will reattempt a few times upon failing, see here: https://github.com/j3k0/cordova-plugin-purchase/blob/master/src/js/product.js#L189:L193