Easy-digital-downloads: Double PayPal payment processing

[stephywells]

Bug Report

Expected behavior

When a PayPal payment is submitted, I expect the user value to go up by the value of the transaction. I also expect the transaction to only send one notification email, and create only one license. That payment should also only have one set of log messages on the payment i.e. 'Status changed from Pending to Complete'.

Actual behavior

At least half of the PayPal payments are being marked as complete twice. I have to watch for duplicate payment notification emails so I can delete the extra licenses generated ad recount the user totals. This may also affect report accuracy, but I haven't looked into that.

Steps to reproduce the behavior

1. Submit a payment with the PayPal Standard gateway
2. After the IPN notification is received, the payment is processed twice.

Possible fix

I've made this change on my site, but haven't yet verified if it solves the problem. This fix does not change the payment status unless it is different from the previous status.
https://github.com/easydigitaldownloads/easy-digital-downloads/blob/master/includes/payments/functions.php#L292

if( $payment && $payment->ID > 0 && $payment->status !== $new_status ) {

[pippinsplugins]

@stephywells does your PayPal IPN history show there being multiple IPN messages being sent (i.e. EDD is picking up two messages)?

[stephywells]

Nope, just one IPN per transaction. Maybe it's a combination of IPN and PDT both marking the same payment as complete?

[stephywells]

And still got another double after making that code change.

Trying this line now https://github.com/easydigitaldownloads/easy-digital-downloads/blob/master/includes/gateways/paypal-standard.php#L926

if( false !== strpos( $body, 'SUCCESS' ) && $payment->status !== 'publish' ) {

[shazahm1]

I also noticed this behavior for at least a month now but have not been able to track the cause. For me, it also seems related to only PayPal transactions. I also have the Stripe gateway and I have not found one instance where this occurred with Stripe.

I dug into this again this morning after seeing this issue opened...

I ran this query in my DB

SELECT * FROM `[REDACTED]_comments` WHERE comment_type = "edd_payment_note" ORDER BY `[REDACTED]_comments`.`comment_ID` DESC

Then I did an in browser text search for Status changed from Pending to Complete and scanned the page for double instances of this string at the exact same time to the same post ID.

The oldest occurrence, payment ID 445039, I found dated back to 12/22/2017. Payment marked completed twice by the "EDD Bot". In this instance only a single license was created.

The oldest occurrence I found, payment ID 445562, where two licenses were generated due to the payment being marked completed twice was on 12/30/2017.

So, perhaps something changed in an update in around this time frame to cause intermittent marking as completed twice which in turn would intermittently generate two license keys. I tend to trail in EDD updates by a month or so. I see PDT was added in the 2.8.13 update on Nov 20. So perhaps this is when the bug was introduced.

[stephywells]

I'm still getting doubles. My code changes are not making a difference.

[shazahm1]

Unsurprisingly, in addition to duplicate licenses being generated, AffiliateWP also credits the affiliate twice for the purchase.

I've put EDD in debug mode to see if logging offers a clue on the cause.

[shazahm1]

Enabling debug has not revealed anything useful. Here are the log entries with the array data removed for three purchases.

First purchase is a bundled price variation, only one set of licenses created as expected.

1. PayPal arguments: Array
2. Attempting to verify PayPal payment with PDT. Args: Array
3. PayPal IPN endpoint loaded
4. edd_process_paypal_ipn() running during PayPal IPN processing
5. encoded_data_array data array: Array
6. Attempting to verify PayPal IPN. Data sent for verification: Array
7. IPN verified successfully

Second purchase is simply a single item. This purchase had two licenses created and the EDD Bot notice twice Status changed from Pending to Complete.

1. PayPal arguments: Array
2. PayPal IPN endpoint loaded
3. edd_process_paypal_ipn() running during PayPal IPN processing
4. encoded_data_array data array: Array
5. Attempting to verify PayPal IPN. Data sent for verification: Array
6. Attempting to verify PayPal payment with PDT. Args: Array
7. IPN verified successfully

The third purchase is just another single item. Only a single license was created as expected:

1. PayPal arguments: Array
2. PayPal IPN endpoint loaded
3. edd_process_paypal_ipn() running during PayPal IPN processing
4. encoded_data_array data array: Array
5. Attempting to verify PayPal IPN. Data sent for verification: Array
6. Attempting to verify PayPal payment with PDT. Args: Array
7. IPN verified successfully

These three purchases occurred in the exact sequence as listed above. Meaning there were no other purchases in between. Each purchase was several hours apart.

[sunnyratilal]

This is a race condition. IPN and PDT are both triggering the actions at the same time.

Initial thoughts are implementing a mechanism for locks or a queue to fix this.

A short term fix will be to disable PDT from PayPal settings.

[shazahm1]

I see a way to disable IPN in settings, but not PDT. Is there a way in code to disable? That way I can confirm that is the cause.

[sunnyratilal]

My Account → My Profile → My selling tools → Website preferences → Payment Data Transfer

PDT is a fallback for IPN so it is generally recommended that you keep it on, however, it would be great if we could get verification that the race condition is what's causing the issue.

[shazahm1]

Ok, I've disabled PDT. I may need a couple/few days of transactions to verify as this would occur only once or twice a day depending on sales volume.

[pippinsplugins]

@shazahm1 removing the PDF token from EDD settings would also disable PDT.

[shazahm1]

Disabling PDT seems to have corrected the duplicate issue. I would have expected to see at least one by now and I have not.

Not sure how adding sleep actually corrects the issue :/ sure it might reduce the occurrence but its not a fix.

A payment queue would be the proper solution with perhaps a payment meta attached on whether or not the gateway approved the purchase or not vs. using the payment status which can differ from the actual gateway response; eg. payment status of refunded where the gateway originally approved the purchase.

[pippinsplugins]

@shazahm1 the sleep approach is a fix. This only happens because both PDT and IPN are marking the payment as complete at the same time. It's a race condition. When marking a payment as complete, there are checks performed to see if the payment has already been completed. If a payment is already completed, the process is stopped. The problem here is that both PDT and IPN detect the payment as pending since they're happening within MS of each other. By delaying the IPN processing (which has no impact on the customer), we allow PDT to finish first. Once it's finished, the IPN will properly detect the payment is completed.

[shazahm1]

@pippinsplugins I disagree that using sleep is a fix... moving on...

I enabled PDT in PayPal and applied the changes made by @sunnyratilal.

The very first PayPal purchase made after uploading the change was marked Complete twice. Likely because the sleep should occur before do_action( 'edd_verify_paypal_ipn' ); not after???

[shazahm1]

After monitoring this for the remainder of the day, the sleep does seems to stop the licenses from be generated twice.

However.

The payments are still being marked Complete twice by the "EDD Bot".

AND

Not mentioned before... one of the other side effects of the bug was that the email admin notification is sent twice. I presume the customer email is being sent twice too.

Even with the sleep fix, these emails are sent twice. As well as being noted complete twice.

[pippinsplugins]

You're right that a queue system is the better fix. That is, however, a _much_ larger change. We will probably introduce a queue system at some point, but in the interim we need a quick fix that doesn't require _extensive_ changes that have a high probability of causing unexpected and unforeseen issues.

@sunnyratilal the do_action( 'edd_verify_paypal_ipn' ); needs to run _after_ the sleep() call, otherwise it doesn't actually do anything :)

[pippinsplugins]

@shazahm1 @stephywells new fix pushed up if you care to test again.

[stephywells]

I've got this in place for testing. I'll watch for doubles today. Thanks!

[shazahm1]

I've moved the action to match the change made by @sunnyratilal

I'll reports back.

[shazahm1]

I received one PayPal purchase since making the change. The payment was marked completed only once and only a single set of licenses were created as expected.

However...

The EDD Bot did not record the PayPal Transaction ID in the payment notes. The transaction ID still showed in the Payment Meta metabox, so it was still properly recorded (I assume).

Of course this is only a single data point. I'll follow up again after the weekend.

[pippinsplugins]

The transaction ID in notes is a legacy item (before we had a dedicated meta field for it) and that only gets logged during the IPN. It's superfluous data that's not needed.

That means the PDT processed it properly and the IPN detected it was already completed and so bailed.

Looks like it worked!

[shazahm1]

After several days the PayPal transactions seem to be working with no duplicates being created. In one instance it does seem IPN finished processing before PDT. Basing that purely on the existence of the transaction ID in the notes per your previous reply. In that instance, the purchase looks correct, no duplicates.

[pippinsplugins]

Great!

[shazahm1]

Just thought I would follow up on this. Even with the sleep(5) I still get the occasional duplicate processing. Just 2 occurrences since, that I know of. I just increased the slep to 6.

[stephywells]

I'm also still getting occasional duplicates.

[stephywells]

I'm getting bunches of duplicates today. I think every PayPal payment has been duplicated. I'm on v2.9.8.

[cklosowski]

@stephywells will take a look shortly, thanks for letting me know.

[cklosowski]

So looking through this, because of the variations in the time between the PDT and IPN, the only consistent way to avoid this is to have the PDT be the only 'complete' handler when the PDT token is present.

There is evidence that these PDT and IPN calls are happening within milliseconds of each other, which means even updating a DB and having the value come back as publish by one of them isn't likely.

Going to look at this approach to see if it's ideal for moving forward.

[pippinsplugins]

@cklosowski I have a concern with that approach.

Customers that do not successfully return to the success page on the site will _not_ get their order completed. This could happen due to:

1. Browser crash
2. An unintentional window closure
3. A click away from the PayPal redirect screen
4. A PayPal issue resulting in the customer not getting redirected

[cklosowski]

@pippinsplugins yeah that does pose some issues...Let me see if I can work around those.

[cklosowski]

@stephywells @shazahm1 So, based off the above feedback, and considering what I think is going to have to be a significant refactor, the suggestion at this moment is to just remove your PDT from the settings. This will allow IPN to be the only listener and not run into this race condition.

I know this isn't a long term solution given the history of IPN delays, but until we can figure this out with a refactor of how we can avoid the race condition, I think it's best to avoid the accounting issues you're seeing with duplicate payments.

I'm leaving this open until I can come up with a better solution than the one I committed above, based off the feedback from @pippinsplugins

[davidsherlock]

Another report of what I believe is this issue:

https://secure.helpscout.net/conversation/768205475/99845?folderId=1847245

[stephywells]

I switched over to PayPal Express to solve the problem. It might be helpful to suggest this for others.

[pippinsplugins]

Another case of this happening: https://secure.helpscout.net/conversation/941080363/129942/