Paypal WPS: Order status inconsistent, sometimes set to "complete" sometimes "payment received"

I hate working with paypal because the ability to test the gateway is such a pain in the *** - that is why I don't use this gateway myself. So I can only really help with committing patches to fix any issues people find.

By the sounds of things its working correctly if everything happens in the correct order, ie: if all the messages coming from Paypal are in the correct order it works, correct? Its just when things happen out of the order the logic in the Paypal gateway code is not equipped to handle that case.

Subscribing.

Using latest dev of uc_recurring, when a Paypal WPS payment is completed, and an IPN notification is received, the order status is changed from In Checkout to Pending, despite the fact that I have Conditional Actions configured to change the status to Completed upon full payment+order status update.

I'll be digging into this more.

If you are keen on fixing paypal, lets try and fix it at its source, as the moment uc_recurring has to add in all this duplicate code because ubercart does not allow us to get access to its IPN messages.

#781720: Refactor the Paypal WPS IPN code

As for fixing this issue... we (ubercart & uc_recurring) do log the IPN messages to the database so if we get a subscription created message after the payment received messages, maybe we can look for an existing message in the db that says payment has been received and then process it as well so we don't end up in this state.

@Univate: Thanks! Will take a look at the patch in your linked Issue. Hopefully that should solve that particular issue. Would love to help test.

That patch wont solve this issue, its just a step towards making uc_paypal more extensible so modules like this don't have to duplicate effort. The problem in this issues seems to be messages being received from paypal out of order and what I mentioned in #9 is probably what will need to be done to solve this issue.

This will sound obvious, but: "did you check the order a few minutes later?"

In my own custom cart, I've often times seen paypal takes minutes to update the IPN, in which case things are still technically pending. Eventually it has always gotten updated, though. From what I read in this thread, though, that may not be the issue since it does work correctly if uc_recurring is not in the loop. Hmm.

Cheers,

Brandon

I think its worth mentioning that Paypal WPS no longer works with ubercart-2.3: #781010: Patch to Ubercart might break recurring Paypal WPS

To follow up on this, I have PayPal WPS still working with Ubercart 2.3 (have not upgraded yet) but, it seems that in this case an IPN is sent to the site twice; the first time, it contains a "payment_status" flag. The second time, it doesn't. This causes the order to go from "In Checkout to Completed" and then "Completed to PayPal Pending".

I could fix this with another Conditional Action, but that seems like more of a band-aid. I didn't see anything for a Default case in _uc_recurring_hosted_paypal_ipn_payment() (in uc_recurring_hosted/uc_recurring_hosted.paypal_ipn.inc) that might cause this, other than the fact that it doesn't know what to do if the $ipn->payment_status doesn't exist.

Any thoughts?

#17: Yours look right, but I'm also assuming that ipn2 comes in after ipn1? In my case, ipn1 (the notification from PayPal that is of txn_type "subscr_signup". Since this, in my case, doesn't include a "payment_status" element, that logic is failing, and so the payment status is being set to Paypal Pending.

I added a bit of logic to the code:

if ($ipn->payment_status) {
...
}

So that it only switches for payment_status if a payment_status exists.

I tested this on a live account just today, and it worked perfectly. I got both txn IPNs logged in for the order, the recurring fee (and role) has been setup, and everything else seems to be fine. The condition I'm checking for shouldn't affect anything other than setting the order status, and it was doing so by checking payment_status anyway - so it shouldn't have any side effects, but if it does let me know.

For me this solved my issue though I'm not sure it's the same as the OP.

But #13 since you're the OP I'll mention that I don't think your issue is necessarily uc_recurring's fault. Did you double check your Conditional Actions? There might be another module that is hooking into uc_recurring that's affecting the order status. In my case I'm using uc_recurring and uc_roles to add a "subscriber" role to a user's account, along with User points. The only place I have seen it act inconsistent in updating order status is as I've described above - and for my case it involves the fact that the order statuses are hard-coded into the uc_recurring module.

I'd suggest looking at your CA configs and other contrib modules and see if any of them could be overriding the status. Can you post the actual "logs" from your order? The ones that say "Order status changed from foo to bar"?

Yeah, I just add that condition to the beginning of that function, just before the switch($ipn->payment_status) line. I need to check my current code and see if using the patch from #781720-1: Refactor the Paypal WPS IPN code impacts any of this stuff. Not sure if you gave that a shot yet but it seems to move that function around.

Soon as I can roll a patch I will, but it's only a couple of lines. :)

I'm having similar issues to those described in this thread. I've turned on detailed logging and will report any significant findings. Did anyone ever come up with a solid solution for this issue? I tried the suggestion in #18 but that appeared to have no effect. As the switch doesn't have a default case, I'm not sure what the intention of that change was. But that suggestion was from a few months ago, so maybe that change was made on a different code base. I'm on 6.x-2.0-alpha5

Thanks!

Worth noting that I've seen orders stuck in both "Payment Received" and "PayPal Pending".

I'm curious whether there is a race condition within the "uc_recurring_hosted_paypal_ipn" function. I see watchdog entries like this in the log (oldest to newest):

Receiving recurring IPN at URL for order 4433.
Receiving recurring IPN at URL for order 4433.
PayPal Recurring IPN Transaction Verified.
PayPal Recurring IPN Transaction Verified.

I'm not terribly familiar with this code (yet), but I would have expected to see this:

Receiving recurring IPN at URL for order 4433.
PayPal Recurring IPN Transaction Verified.
Receiving recurring IPN at URL for order 4433.
PayPal Recurring IPN Transaction Verified.

I'm assuming that "uc_recurring_hosted_paypal_ipn" is triggered by the external notification from PayPal, and that if the two notifications arrive sufficiently close together, it is possible that it is called twice at the same time, once for each notification. This would become more likely if there are any delays due to database congestion, server load, etc. that delay the execution of the first invocation.

Does that sound like a possibiity to people more familiar with how all this works?

Would be interested to find out if adding a lock/unlock on the paypal db table at the start/end of that IPN function would help, something like:

db_lock_table('uc_payment_paypal_ipn');
...
db_unlock_tables();

Thanks, univate.

My first attempt using your code failed - the order stuck at Pending with no ipn activity logged. This is only my second experience with table locking, so I could be way off base. But per http://dev.mysql.com/doc/refman/5.1/en/lock-tables.html, a session that locks tables can access only its locked while the lock is held. And as multiple tables are accessed within that function, your suggestion might not work as intended.

That aside, I'm very interested in your idea. I have memcache available, so I tossed a memcache lock around that function's body to see what would happen. My test transaction went okay, but I've had sporadic success reproducing the problem myself. So I'll run with the memcache lock awhile, see what happens, and report back. I realize this isn't a general solution, but at this point I'd be happy just to learn something.

I've processed enough orders to report back initial results. As expected, adding the lock resolved the race condition. So in the log, I now see:

Receiving recurring IPN at URL for order 4433.
PayPal Recurring IPN Transaction Verified.
Receiving recurring IPN at URL for order 4433.
PayPal Recurring IPN Transaction Verified.

Instead of:

Receiving recurring IPN at URL for order 4433.
Receiving recurring IPN at URL for order 4433.
PayPal Recurring IPN Transaction Verified.
PayPal Recurring IPN Transaction Verified.

That's a good thing, and a necessary first condition to fixing the stuck transactions. However, I am still seeing some orders get stuck while others go through fine. Presumably, this is due to the timing issues discussed by others earlier in this thread, but I haven't had a chance to really examine it yet. At the very least, all of my "stuck" orders have looked the same, whereas before there were two or three different (wrong) ways they could look. Consistent is good - much easier to debug.

To implement the lock, I had to change a few things in the "uc_recurring_hosted_paypal_ipn" function. That's because it previously could return directly from the switch statement, and that would have bypassed releasing the lock. I encapsulated the actual locking in two new functions:
uc_recurring_hosted_get_lock
uc_recurring_hosted_release_lock

There remains the issue of how to properly implement a lock. I used memcache, because I was already using it for something else and it was quick and easy. But we can't depend on people having it. I found mention of locking here:
http://api.drupal.org/api/drupal/includes--lock.inc/group/lock
Would this be appropriate?

I've attached a patch for what I'm currently doing, in case it helps somebody. To try different locking strategies, you should just have to modify the bodies of my two new (and very short) functions. Be sure to apply the patch offline and tweak for your server setup before trying to actually execute anything.

--Begin Disclaimer--
WARNING! DANGER! CAUTION! DO NOT ACTUALLY APPLY THIS PATCH ON A LIVE SERVER! IT DEPENDS ON CODE THAT YOU WON'T HAVE! IT WILL BREAK! USING THIS PATCH IS MORE DANGEROUS THAN RUNNING WITH SCISSORS! EVEN THE REALLY SHARP POINTY ONES, NOT JUST THE DULL ROUNDED ONES LIKE WE USED IN KINDERGARTEN!
--End Disclaimer--

I realized I didn't put in a sleep-retry loop in my memcache lock (duh) so that was doomed to failure. I've corrected it now. Orders have slowed down for the moment, but I'll be watching to see if I still have stuck orders with this correction.

I also tried the drupal lock_acquire/lock_wait/lock_release functions, but found they weren't available on my Drupal installation. A quick Google revealed this to be a known issue, so I went back to memcache for now.

The attached patch has a now-hopefully-correct memcache lock, plus commented-out drupal locking, in case there is anyone who whould like to give that a try and whose installation is happy with those functions.

Again, unless you change the code yourself, the patch depends on my custom memcache code, and IS NOT USABLE ON YOUR SITE AS-IS.

Was not even aware of those lock functions. That looks to be exactly what is needed here.

If the issue you are referring to is #732064: "Call to undefined function lock_acquire", locale module, that appears to be fixed in the current 6.x release.

I'm still seeing stuck orders, even with the locking. I can't see anything different in the ordering or content of the PayPal IPN messages in the detail logs for working vs. nonworking orders.

How does uc_recurring fit into the Ubercart's overall PayPal processing system (with which I am completely unfamiliar). My lock prevents simultaneous execution of just the "uc_recurring_hosted_paypal_ipn" function. Is it possible that other Ubercart code is having race condition problems outside the context of my lock, resulting in the issue?

uc_recurring WPS code overrides the ubercart paypal code, it isn't interfering here.

Personally I would like to reduce the need to duplicate code and re-use the core ubercart paypal code, but no-one else seems interested in allowing this: #781720: Refactor the Paypal WPS IPN code

@univate
I think you are right to want to use the ubercart paypal code but it sounds like that code isn't very well written and that team is unwilling to improve it in a timely manner. So others here are leaning on uc_recurring to do it (not really ideal). For us, the WPS code in uc_recurring isn't acceptable because it only supports a single recurring item but still allows for checkout. That was a real pain to fix each order that came in and we quickly disabled WPS support.

I see only two ways that WPS support can work in ubercart (based on feedback from our current cart developer). The WPS API is intentionally designed to support only 1 recurring order per checkout. So, either:

1. We would use "reference transactions" (http://drupal.org/node/854536) to handle multiple recurring per order. However, it is possible that "reference transactions" are only supported by WPP.

or

2. We would allow an option to block users with a custom message and redirect back to the cart. Users would then be forced to remove all but 1 recurring item, if they then select Paypal payment method.

We are currently funding the development of #2 in the hopes of finally getting rid of our old cart solution but that is far less than ideal of a solution.

I remain completely baffled on why some orders are getting stuck.

I added more detailed logging, including to-the-second timestamps. I just compared a stuck order to a successful one, and found absolutely no difference in the order or content of the IPN messages. (Things like customer names and order numbers differed, but those are expected to change.) The timestamps indicate that the locking is doing its job and the IPNs are now being processed sequentially rather than concurrently, and in the same order between the stuck and successful order.

What else in the code might be subject to race/timing issues or nondeterministic ordering? Are there any identical module or action weights that might be competing for which executes first for different orders? I know I'm reaching here, but *something* is up.

Ok, finally observed something that may be useful. This goes all the way back to comments #1 and #2 in this thread, but I was either too dense or too confused to recognize it at first.

For good orders, if I pull up the order detail page, the last admin comment is "Order created through website". For stuck orders, that comment either does not appear, or appears before the IPN comment about "Payment reported".

Near as I can tell, that comment is created only by Ubercart code, not uc_recurring code, in the section that ends up with an order getting set to Completed. So there appears to be a race condition between PayPal's IPNs (and the related uc_recurring code) and whatever is triggering Ubercart to add that comment. Does that make sense, and any suggestions what to do about it?

I'm getting pretty worn out on this issue, and I'm getting really tempted to just hack in something. My first thought is a call to function uc_cart_complete_sale (file uc_cart.module) from _uc_recurring_hosted_paypal_ipn_payment (file uc_recurring_hosted.paypal_ipn.inc).

I fully appreciate that cleaning up Ubercart's PayPal processing is the better overall solution. But I'm tired of getting hatemail from customers, so I really need to get fix (even a hackish one) working soon. After that, I'm more than willing to help test more comprehensive patches on our site. (We have a development site where I could try out some speculative things separate from live code.)

I made some changes to both Ubercart and uc_recurring code, and have now been running for a few days, and a number of orders, with nothing getting stuck. The final issue was that the original code had a three-way race condition:

1) the "subscr_payment" IPN, handled by uc_recurring
2) the "subscr_signup" IPN, handled by uc_recurring
3) the Ubercart "cart/checkout/complete" menu item, which results in calls to uc_cart_checkout_complete and uc_cart_complete_sale

My previous locking efforts addressed #1 and #2, but not #3. Addressing that required three things:

1) make subscr_signup not bump to PayPal Pending if status is already Completed
2) bump to Completed upon subscr_payment
3) don't invoke hooks and triggers upon cart/checkout/complete if status is already Completed

The one remaining thing that I might should do is to add a lock in uc_cart.pages.inc to prevent simultaneous execution of #3 with #1 or #2. But this hasn't been a problem thus far. If it is, the same locking functions could be employed (and in fact must, so that the lock is shared by all three events).

I don't pretend to understand everything in Ubercart, and my rather hackish fix probably fails for all sorts of other store configurations besides mine. And (as mentioned in comment #25) my lock depends on my own custom code, so the attached patches WILL BREAK ANYONE ELSE'S STORE UNLESS THEY CHANGE TO THEIR OWN LOCKING MECHANISM!!!!

Still, it is working for me at the moment, so I'm happier than I was a week ago.

I'm still willing to try out more comprehensive Ubercart/PayPal integration changes, if someone will tell me what I can do to be helpful.

Awesome work. I think if these race conditions are verifiable and easily reproduced, then we should definitely consider using lock_acquire() and lock_release() as demonstrated on that API page. Since it's a pluggable API you should be able to use it with something like memcache (though I haven't dug into it that far yet, that's just how the page reads).

Race conditions like this also lead to some CA weirdness, like if we have an order that contains shippable and non-shippable items, there are times when our "set order status to 'Pending Shipping' if order contains shippable items" Action fails, because of the digital downloads. In other words it appears that the order of operations changes due to the race condition, resulting in some anomalies.

+1 for this, thanks for your detailed investigation and hard work. I bet a lot of us contrib maintainers could benefit from this locking mechanism, especially when involving Ubercart.

Subscribe

Thanks for your hard work, will test this when I can.

The subscr_payment IPN is the most common IPN you will receive as it gets sent on each renewal, so I don't think putting a sleep here is a good idea, which will keep that apache/php process active (potential blocking other requests) for 20seconds.

We should at least check and only do this on the first payment - there shouldn't be a problem with recurring payments.

I am sure there is a better way to solve this problem without a sleep at all though.

Hey guys,

I think I am seeing a similar problem on one of my sites. I am using PayPal WPP which is working to a degree... but I cannot get roles to grant when the payment is received. I have pushed the conditional actions around repeatedly in an attempt to resolve this - I have set the role to fire when payment is received, I have set the order to fully complete when payment is received, I have gone through everything I can think of to make this work. The only way I can get the role to grant is if I go in and "complete" the order manually (it simply will not complete on its own).

Forgive my ignorance, but is this an extrapolation of the same issue?

-kirk

Update: It looks like my problem was related to a hang up with another module. Appologies for thread-crashing.

Interested to know whether anyone has made any progress on this. I'm still hitting the same issue: User is sometimes returned from Paypal WPS with the order state set as 'Payment Received' not complete and is not therefore given the correct permissions as a subscriber. I'm using:

Ubercart 6.x-2.x-dev
uc_recurring 6.x-2.x-dev
and a Paypal WPS account

The issue seems to be the same on both Sandbox and Live testing. My PHP skills and time are not enough to help fixing the issue but I'm now stuck. Is there some workaround we could use with altering the trigger / conditional action until wiser heads have been able to fix this?

Running a UK business and I seem to be slightly stuck with uc_recurring. Does anyone else in the UK have it working in production? Alternatives to Paypal WPS seem to be Paypal WPP - does anyone have this working with a recurring subscription? How about Sagepay?

@univate - I'd love to sponsor a fix for this for production use - impressed with uc_recurring and would love to use it. Understand that WPS is a foobar to debug but outside the US, Paypal or Sagepay are the uc-recurring alternatives. Lot of users seem to feel that WPS is safer / quicker than entering credit-card details.

If sponsorship would help then let me know although realise you may be snowed with other issues....

@that0n3guy - could you summarize what we need to do to make this all work with WPS - its a little confusing following all the posts in the thread - I am also more than happy to bounty this to get it working well.

I recently had this issue on 6.x-2.0-alpha6, however this issue seems to be resolved in 6.x-2.0-beta1 and in 6.x-2.x-dev ( explanation below ), as a result I'm marking it as "fixed" -- feel free to reopen if this is not the case

----------

In Summary, paypal IPN was sending two statuses back, subscr_signup and subscr_payment. If subscr_signup came second, the payment status would be marked from "Completed" to "Payment Received". @that0n3guy proposed two fixes, one in comment #36, which he then simplified down to comment #41. However, with some other fixes in the more recent versions, the changes in comment #41 are no longer needed because..

Comment #41 was proposed because in 6.x-2.0-alpha6, the flow was

1. uc_recurring_hosted_paypal_ipn ( with txn_type = subscr_signup )
2. uc_recurring_product_process_order
3. uc_recurring_invoke
4. uc_recurring_hosted_paypal_wps_process
5. uc_order_update_status ( this would change from complete back to payment received )

However, in both 6.x-2.0-beta1 and 6.x-2.x-dev, uc_order_update_status was removed the flow is now

1. uc_recurring_hosted_paypal_ipn ( with txn_type = subscr_signup )
2. uc_recurring_product_process_order
3. uc_recurring_invoke
4. uc_recurring_hosted_paypal_wps_process