Stock being reduced twice for one order

Is this a clean install of D7 Ubercart or is it an upgrade from an old version prior to the previous fixes? Have you modified any of the stock rules? Do you have any contributed modules which affect stock or modify the checkout process? The stock reduction is independent of the auto return (or is supposed to be) because we can't assume that will ever happen.

You might want to take a look at the other issues in this queue related to IPN, especially #2143347: PayPal stuck in Pending due to IPN received twice from PayPal - it's possible what you're seeing is related to one of those other issues.

I wonder if it's to do with the rules used by Ubercart to decrease stock and send out order notifications on checkout complete. Looking at the uc_paypal_ipn function, it does complete the ubercart order using uc_cart_complete_sale which in turn calls
rules_invoke_event('uc_checkout_complete', $order);

Very interesting as we are seeing a similar issue. Our instance of Ubercart is 7.x-3.8 and was upgraded from 6. Once in a while, an order will be see a PayPal IPN come back (just one in our situation) and it will trigger two order confirmation emails to the customer and decrements the stock levels twice. This both confuses the customer and requires us to watch for these events as our stock levels will be wrong. This is a relatively rare event which makes it all the more difficult to diagnose. Our rules for Ubercart are pretty standard:

E-mail an order update notification
Machine name: uc_order_update_email_customer, Weight: 0
E-mail requested for order status update Default edit disable clone export

Update order status on full payment
Machine name: uc_payment_received, Weight: 0
A payment gets entered for an order Default edit disable clone export

Decrement stock upon order submission
Machine name: uc_stock_decrement_on_order, Weight: 0
Customer completes checkout Default edit disable clone export

In terms of emails in the log here is a normal order:

smtp 06/09/2015 - 13:00 Sending mail to: service@xxx Anonymous (not verified) ***Admin email***
smtp 06/09/2015 - 13:00 Sending mail to: xxx@hotmail.com Anonymous (not verified) ***Order receipt***
smtp 06/09/2015 - 13:00 Sending mail to: xxx25@hotmail.com Anonymous (not verified) ***Account setup***
uc_paypal 06/09/2015 - 13:00 IPN transaction verified. Anonymous (not verified)
uc_paypal 06/09/2015 - 13:00 Receiving IPN at URL for order 5183. Array... Anonymous (not verified)

And the most recent duplicate event:

smtp 06/09/2015 - 21:37 Sending mail to: service@xxx Anonymous (not verified) ***Admin email duplicate***
smtp 06/09/2015 - 21:37 Sending mail to: yyy@gmail.com Anonymous (not verified) ***Order receipt duplicate***
smtp 06/09/2015 - 21:37 Sending mail to: service@xxx Anonymous (not verified) ***Admin email***
smtp 06/09/2015 - 21:37 Sending mail to: yyy@gmail.com Anonymous (not verified) ***Order receipt***
uc_paypal 06/09/2015 - 21:37 IPN transaction verified. Anonymous (not verified)
smtp 06/09/2015 - 21:37 Sending mail to: yyy@gmail.com Anonymous (not verified) ***Account setup***
uc_paypal 06/09/2015 - 21:37 Receiving IPN at URL for order 5189. Array...

Perhaps it has something to do with the ordering of these events. Need to puzzle over this a bit more. If anyone has suggestions on what to look at or any further diagnostics we could set up be glad to do so.

Interesting. The duplicate emails and stock decrements happened again. It is usually a rare event but now once each day. I am going to have to consider a patch to be sure the email/stock decrement isn't done twice. Have to look at the code. Here in sequence is an order with duplicate emails/stock decrement and the one before it which worked perfectly. Very strange.

smtp 06/10/2015 - 18:40 Sending mail to: service@ Anonymous (not verified)
smtp 06/10/2015 - 18:40 Sending mail to: service@ Anonymous (not verified)
smtp 06/10/2015 - 18:40 Sending mail to: @magma.ca Anonymous (not verified)
smtp 06/10/2015 - 18:40 Sending mail to: @magma.ca Anonymous (not verified)
smtp 06/10/2015 - 18:40 Sending mail to: @magma.ca Anonymous (not verified)
uc_paypal 06/10/2015 - 18:40 IPN transaction verified. Anonymous (not verified)
uc_paypal 06/10/2015 - 18:40 Receiving IPN at URL for order 5193. Array... Anonymous (not verified)

and the normal:

smtp 06/10/2015 - 17:28 Sending mail to: service@ Anonymous (not verified)
smtp 06/10/2015 - 17:28 Sending mail to: @hotmail.com Anonymous (not verified)
smtp 06/10/2015 - 17:28 Sending mail to: @hotmail.com Anonymous (not verified)
uc_paypal 06/10/2015 - 17:28 IPN transaction verified. Anonymous (not verified)
uc_paypal 06/10/2015 - 17:28 Receiving IPN at URL for order 5191. Array... Anonymous (not verified)

This could be related to #1669968: hook_uc_checkout_complete() is called outside of checkout process (when payment is entered) since Paypal code effectively calls uc_cart_complete_sale() twice during payment processing. Once through uc_payment_enter() and the second time directly. This could trigger the checkout complete rules twice if a new user account is being created during checkout. That would explain the intermittent nature of the bug as it would not occur for existing user account (whether logged in or not).

tinker,

yes - thanks so much for pointing out your fine work on the patch. The problem is very intermittent - just happened again that I am truly at a loss as to how to narrow it down further. I will however re-read the thread you started and dive into the patch. This could be quite a breakthrough if this is the problem and will likely have to implement the patch, test then wait and see if this is actually the root cause as I haven't been able to diagnose it on my own so far.

Appreciate your contribution!

@Allthegearnoidea, Thanks for testing and reporting back on patch #37 from #1669968: hook_uc_checkout_complete() is called outside of checkout process (when payment is entered). I am very happy to hear that it appears to be working for this issue too. I should warn against applying the patch to a live site before thorough testing as I have not run the 7.x version on a live site and have not been using PayPal payment processing. I have however been running the 6.x patch for over a year without issue with Authorize.net and ran automated simpletest on the 7.x version without issue. The only real difference between the versions is the way passwords are stored for new accounts. There could be a problem with the 7.x version not displaying the new user's password on the checkout completion page and instead will show 'Your password' text. Please keep an eye out for this and let me know if it happens. If the patch does indeed fix this issue could you please post your future findings in the other issue queue to expedite the patch being accepted.

@alh If you could also test the patch it would be of great help. With confirmation of fix from you we could close this issue as a duplicate and advance the other issue.

Hi guys,

I have applied the patch to our test site and ran some test orders. I am however having some difficulty as the Instant Payment Notifications from PayPal on the test site are not working properly. This has of course nothing to do with the patch but the extreme difficulty we have with PayPal`s sandbox which delivers IPNs that are different than the live site! So on Monday, I am going to do a work around to ignore the invalid fields in the sandbox IPNs. Assuming all goes well on that front, I will try it on our live site. I should add that even with the difficulty with the sandbox IPNs, orders are being processed correctly. I will report in more detail once I get the workaround in place.

In the meantime, we are not seeing the annoying duplicate email and stock decrements on our live sites right now. I am baffled as to why that is to be honest. It would be great if this was predictable, i.e. found only with a certain class of users but not in our case.

But hope springs eternal that we can beat this one into submission.

OK, figured out what the IPN problem was. Wrong URL being used to verify IPNs in the sandbox. Once fixed, IPNs are being processed properly, email sent and stock decrements being done. I observer however two errors in the logs:

Notice: Undefined variable: order in uc_payment_enter() (line 496 of /home/anytests/public_html/sites/all/modules/ubercart/payment/uc_payment/uc_payment.module)

and

Notice: Trying to get property of non-object in uc_payment_enter() (line 496 of /home/anytests/public_html/sites/all/modules/ubercart/payment/uc_payment/uc_payment.module).

This error occurred during the processing of the sandbox IPN hence was generated due to a call to the URL for the order:

test-site/uc_paypal/ipn/4827

So something a bit amiss here and will dig deeper to see what the problem is.

@alh Your errors cannot be caused by the patch since variable $order is defined before it is used and no $order->property call exists in the function uc_payment_enter(). What is the code at line 496 in file uc_payment.module

Hi tinker and Allthegearnoidea,

you are absolutely right and my bad. Another patch that I was testing and should have backed out before testing this one! I will do so today and report back.

Hi again,
rolled back the other patch, re-installed this one and ran a test order. Worked perfectly on the test site. This was a new user who checked out anonymously. Order emails sent, stock decrement happened and order flipped to payment received as expected. I am going to run another couple of test order with other states and will report back but this is very encouraging.

So have now run three tests in the sandbox and all went well. Tested:

Anonymous check-out with a new customer as mentioned above
Anonymous check-out with a returning customer
Check-out with the customer logged in

I am now considering going live with this on one of the three sites. Start there then if all goes well migrate to the others.

Thanks again tinker and will continue to report back.

@Allthegearnoidea, Did you notice a decrease in the amount of orders with duplicate stock decrement? If so it may mean you have a compound issue and uc_paypal code needs a fix too. I suggest that you add some code that logs execution of uc_cart_complete_sale() per order as that is the rules event that triggers stock decrement.

You could just add an admin comment to uc_cart_complete_sale()

function uc_cart_complete_sale($order, $login = FALSE) {
  global $user;
  uc_order_comment_save($order->order_id, 0, "uc_cart_complete_sale triggered.", 'admin');

The check the orders that have duplicate stock decrement and see in the admin comments if it was triggered more than once. From the uc_paypal code it looks like it should only be triggered once after the IPN verification.

As to the 'Your Password' issue - this only happens when a new account is created and the user supplied a password during checkout. There is no way around it since we cannot store the unencrypted password and cannot decrypt the password later.

@Allthegearnoidea, Yes that code is in ubercart/uc_cart/uc_cart.module
Search for 'function uc_cart_complete_sale' (around line 854)
Add the following line at the top of the function.

uc_order_comment_save($order->order_id, 0, 'DEBUG: uc_cart_complete_sale triggered.', 'admin');

Please note that if you do this without the patch you will surely get duplicate execution logged for new users. With the patch you should only get one execution. For orders with patch and more then one 'uc_cart_complete_sale' you can copy and paste admin comments (removing any sensitive data) and I might be able to tell if there is a problem with uc_paypal. Here's what I get with test credit gateway.

Before patch:
2015-07-16 11:19 - Credit card charged: $34.00
2015-07-16 11:19 - DEBUG: uc_cart_complete_sale triggered.
2015-07-16 11:19 - The stock level for SWTDU3 has been decreased to 4.
2015-07-16 11:19 - DEBUG: uc_cart_complete_sale triggered.
2015-07-16 11:19 - Order created through website.

After patch:
2015-07-16 11:17 - Credit card charged: $34.00
2015-07-16 11:17 - DEBUG: uc_cart_complete_sale triggered.
2015-07-16 11:17 - The stock level for SWTDU3 has been decreased to 3.
2015-07-16 11:17 - Order created through website.

@Allthegearnoidea, Are you sure you have the patch applied? The double side by side Debug messages suggests you did not.

08/07/2015 - 13:17 - DEBUG: uc_cart_complete_sale triggered.
08/07/2015 - 13:17 - DEBUG: uc_cart_complete_sale triggered.
08/07/2015 - 13:17 - PayPal IPN reported a payment of 0.99 GBP.

On top of that there is definitely an issue with workflow and paypal payment. It is clear that the order is being completed once when the customer checks out then again (twice) when the paypal payment is confirmed. The twice execution when payment is entered should be fixed by patch but the complete sale on checkout is a paypal issue. I would think that the order would not trigger complete sale and go into limbo until payment is completed. Your stock is currently being decreased before the customer has paid. If you look at my log using Authnet you can see that payment is entered before checkout sale is executed (before and after patch).

@allthegearnoidea, You can search for function " uc_cart_user_ensure". If it exists then the patch is applied. FYI, The patch file has all the details of what has changed. [[ SEE COMMENTS ]]

--- a/payment/uc_payment/uc_payment.module [[ SOURCE FILE ]]
+++ b/payment/uc_payment/uc_payment.module [[ TARGET FILE ]]
@@ -509,11 +509,13 @@ [[ LINE NUMBER, CHARACTER NUMBER ]]
     ->execute();
 
   $order = uc_order_load($order_id, TRUE);
+  // Account is the user who entered the payment and not neccesarily the order
+  // customer.
   $account = user_load($uid);
 
-  // Ensure user has an account before payment is made. [[ - STUFF REMOVED ]]
+  // Ensure customer account is linked to order. [[ + STUFF ADDED ]]
   if (module_exists('uc_cart')) {
-    uc_cart_complete_sale($order);
+    uc_cart_user_ensure($order);
   }