Repeated order e-mails, although no status change (solved)

[loppan]

Hi!

Having a very strange problem I've been battling with for days. Please help .

I searched and a similar problem is found here : https://forum.virtuemart.net/index.php?topic=140629.15 , but there's no solution in that thread.

I'm currently on VM 3.6.10 and Joomla 3.9.15 (the VM Paypal plugin is v3.6.11).

For credit card payments I have two options for my customers - Paypal and "Quickpay" (a Danish payment gateway).

I chose Quickpay years ago because they are cheap and they happened to have a Virtuemart plugin ready.
Sadly, their plugin hasn't been updated since 2016 (and they say the don't support it anymore) so I don't expect this to work forever. But it has served me fine since 2015.

I recently updated VM to 3.6.10 from 3.4.5. Actually I re-installed the whole site, without any major issues.

I opened the shop a few days ago, made some test orders, and it seemed to work fine.

However, I did notice how certain customers received like a dozen (or more) order confirmation e-mails (instead of just one) and I started investigating.

Regarding Paypal :

I learned that checking the IPN-log is a good place to start. And it's true - on every order where multiple confirmation e-mails are being sent, the status is "Retrying".

Clicking on it reveals several things. The HTTP response code is 500, and it has a number of retries (probably the same number as the number of e-mails).

Eventually the status changes to "Sent", but this can take several hours. And in that time, a lot of e-mails have already been sent out.

I suppose the error 500 is because of a server issue.

However, the order is still "Confirmed" and payment goes through fine. So the IPN sort of, works, I guess.

The thing is - I have done several test orders - all with different currencies - trying to simulate different real situations - and they all go through fine.



In the screenshot above, the latest real order is the one that's currently retrying. The orders above it are my test orders, and they went through without problems.

If I view the order (in VM backend) that's currently "Retrying", it looks like this:



Same thing in the Paypal log file :

Code Select Expand

2020-02-05 19:37:19 DEBUG plgVmConfirmedOrder: order number: 6V5D014179
2020-02-05 19:37:19 MESSAGE plgVmConfirmedOrder: Amount/Currency stored 989 paymentcurrency 124 orderusercurrency47
2020-02-05 19:38:40 DEBUG plgVmOnPaymentResponseReceived: stdClass Object
2020-02-05 19:38:41 DEBUG PaymentNotification, order_number:: 6V5D014179
2020-02-05 19:38:41 DEBUG PaymentNotification, virtuemart_paymentmethod_id:: 10207
2020-02-05 19:38:41 DEBUG validateIpnContent: valid_ipn: VERIFIED
2020-02-05 19:38:41 DEBUG payment_status: Completed
2020-02-05 19:38:41 DEBUG plgVmOnPaymentNotification: plgVmOnPaymentNotification order_number:6V5D014179 new_status:C
2020-02-05 19:38:47 DEBUG plgVmOnPaymentResponseReceived: stdClass Object
2020-02-05 19:39:00 DEBUG PaymentNotification, order_number:: 6V5D014179
2020-02-05 19:39:00 DEBUG PaymentNotification, virtuemart_paymentmethod_id:: 10207
2020-02-05 19:39:00 DEBUG validateIpnContent: valid_ipn: VERIFIED
2020-02-05 19:39:00 DEBUG payment_status: Completed
2020-02-05 19:39:00 DEBUG plgVmOnPaymentNotification: plgVmOnPaymentNotification order_number:6V5D014179 new_status:C
2020-02-05 19:39:28 DEBUG PaymentNotification, paypal_data:: Array2020-02-05 19:39:28 DEBUG PaymentNotification, order_number:: 6V5D014179
2020-02-05 19:39:28 DEBUG PaymentNotification, virtuemart_paymentmethod_id:: 10207
2020-02-05 19:39:28 DEBUG validateIpnContent: valid_ipn: VERIFIED
2020-02-05 19:39:28 DEBUG payment_status: Completed
2020-02-05 19:39:28 DEBUG plgVmOnPaymentNotification: plgVmOnPaymentNotification order_number:6V5D014179 new_status:C
2020-02-05 19:40:15 DEBUG PaymentNotification, paypal_data:: Array

...and on and on and on...

I've read in the forum that Virtuemart isn't supposed to send out e-mails unless the order status is updated. That seems logic. How come it still does in my case?

And then, regarding Quickpay :

What's interesting is that I've had the same issue here - Quickpay does a callback to my site when authorizing the payment - it has happened lately that these also fails with an error 500. In this case, Quickpay keeps re-trying hourly for the next 24 hours. Which means that a new e-mail is being sent to my customer about every hour. Even though the authorization went fine and the money is captured. Yes, this plugin is probably buggy, but still - since the authorization went fine, this wouldn't be a problem if VM didn't keep sending these confirmation e-mails.

Once I try doing test orders (as a "real" customer with a real credit card), the callback goes through fine though. No problem there. So I don't have a chance to re-produce the problem .

If anybody has a slight idea what could be going on here, I would truly appreciate it.
I would also appreciate a suggestion for how to make VM not send e-mails unless the order status is changed.

I will also have a word with my host. But it's difficult since I can't reproduce the problem, since my own orders go through fine.

Please help me .

Thank you in advance!

Best regards

Peter

[GJC Web Design]

you need to find and fix the 500 error

just access your site by the notify url and take it from there.. it has to be a 200 response

index.php?option=com_virtuemart&view=vmplg&task=notify&tmpl=component&lang=

[loppan]

Hi John & thanks for your reply .

When I visit my site with that url I do get status 200 every single time I try.

On my test orders it works as well (I simulate a real customer by using a real card, different addresses, different currencies, logged in our not, all possible scenarios), and I still haven't manage to create a test order that fails.

Still it happens occasionally for my customers. And once it does, Paypal keeps trying to resend the IPN calls for like a full day - which obviously results in a lot of e-mails.

I had one real order this morning and it worked. But another real order from yesterday (through Paypal) keeps retrying - and most likely annoying my customer more and more for every e-mail . (he sounded understanding though).

I'm truly puzzled over this, not sure what to do next :/.

Thanks .

Best

Peter

[GJC Web Design]

Ah Peter...

so .. I guess the next stage is to recreate exactly the POST that is received by your site from the failing Paypal IPN..
something in it is causing the 500

You can do this by creating a html form with all the fields that are in the ipn .. it should be logged in the  #__virtuemart_payment_plg_paypal  -> paypal_fullresponse
and posting it to your notification url

sent  an example form by email -- just put it in the root of your website and call it by browser after changing the post url and fields

[diri]

If those errors occure only occassionally ...

Did you check server access log for times when it happens?

Are there many other requests at site?

If yes: Check for session limit of server.

Such a check is easy to accomplish with SHTML and multiple includes of a PHP file eg only echoing date (echo date('Y') to ensure proper data.
Example:

Code Select Expand

Script 02 (<!--#config timefmt="%a, %d.%m.%Y %H:%M:%S %Z" --><!--#echo var="DATE_LOCAL" -->): <span class="docstrong"><!--#include virtual="/test/date.php" --></span>
<br>Script 03 (<!--#echo var="DATE_LOCAL" -->): <span class="docstrong"><!--#include virtual="/test/date.php" --></span>
<br>Script 04 (<!--#echo var="DATE_LOCAL" -->): <span class="docstrong"><!--#include virtual="/test/date.php" --></span>
<br>Script 05 ...

Stumbled over such issues at Ionos (1und1) hosting. There is a session limit of around 16 and error 500 will be shown latest at 25 calls of this little script.

[loppan]

Ok people thank you very much for your replies but I finally managed to figure this on out.

I use AwoRewards and there were problems with a rule I have that give each customer store credit on each purchase.

I would have spotted it earlier if I hadn't disabled Rupostel's fantastic fatal error plugin, that sends me an e-mail on every error. Once Paypal tried to change the orderstatus to Confirmed my site ended up with a MySQL 1054 error.

I seem to have some google console crawling issues (Google keep trying to crawl my old urls (from before the site re-installation) so I do get LOTS of errors reported due to broken links. Which is my next problem to dig into right now .

But thanks @GJC & @diri for your willingness to help!

Cheers

Peter