magento2: Paypal some orders fail with main.CRITICAL: Wrong order ID:
When using paypal express integration as the payment method on Magento 2.2.2 a small number of orders fail after the payment has been taken by paypal. No order is registered in Magento, but paypal takes payment and sends a confirmation to both customer and store owner.
Looking in the logs the error which seems to be associated with these orders failing is:
main.CRITICAL: Wrong order ID: "000000222". {"exception":"[object] (Exception(code: 0): Wrong order ID: \"000000222\". at .../vendor/magento/module-paypal/Model/Ipn.php:140)"}
Preconditions
- Magento 2.2.2
- Paypal Express Checkout set as Payment method.
Steps to reproduce
- Customer Places Order
- Directed to PayPal page and payment taken
- Redirected to site, order fails and is not logged in Magento.
Expected result
- Once payment has been taken and the customer has been redirected back to the site order is registered with magento.
Actual result
- Payment is taken.
- Paypal redirects to site and sends confirmation email with correct order number.
- Order is not registered in magento.
- Order ID skips failed order (next order number is incremented from failed order, orders list in backend has a gap where failed order would have been).
About this issue
- Original URL
- State: open
- Created 6 years ago
- Reactions: 14
- Comments: 104 (14 by maintainers)
After my comment above I have gathered some additional log data which explains how (in my case) we end up with a valid paypal transaction with no order existing in Magento.
sales_invoicewhich caused the order to be rolled back which reverts the validsales_orderentry.paypal/express/reviewwith the session messageWe can't place the orderwhere they can attempt to pressPlace Orderagain.PayPal gateway has rejected request. A successful transaction has already been completed for this tokenexception will be logged.Explanation of how I found this, and my mitigation.
Finding the error
Step 1 - Capture errors and log them
I added some additional logging to the core paypal controller by using
cweagans/composer-patches. (This log will catch a lot of false positives as address related issues etc will be caught.)Step 2 - Wait until an orphaned order is identified
I would like to try and find a way of doing this programmatically, but as the data doesn’t exist in Magento it is difficult.
Paypal will have a record of the intended order
increment_idwhich we need to proceed.Step 3 - Find the associated quote
This will give you the
updated_attime, this and theremote_ipcan also be used to cross reference with your apache logs to confirm the user journey and that the customer ended up onpaypal/express/review.Step 4 - Get the error log
The log can be found in
var/log/support_report.log, easily identified by searching for “Logging for JIRA-TICKET-123” at around the same timestamp as the quoteupdated_atfield.Step 5 - What we saw
SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction, query was: INSERT INTO `sales_invoice
Emulating the issue locally
I was able to spoof similar behaviour (lock wait timeout, not a deadlock) locally using the following methodology, this should never be done on any environment other than your local!
Ensure that
payment/paypal_express/payment_actionis set toSaleso that invoices are created when the payment is processed.Go through your checkout locally on your chosen store view, do a successful paypal order to ensure the auto increment ids are clean and easily calculable.
Clear your cookies / session / etc. Go through the checkout on the same store view and get as far as https://www.sandbox.paypal.com.
Prepare to lock the
sales_invoicetable by getting the next valuesOpen a database terminal (
magerun2 db:cons) and run the following commands (updating the values based on your output). Leave the window and session open so that the lock persists.Proceed through the paypal checkout process. The callback to Magento should fail and take you to
paypal/express/reviewwhere you cannot progress from. This order is broken.Close your database terminal to release the lock without writing.
Mitigating the issue
To mitigate this error and turn our handling of it from being reactive to proactive I have written an observer.
sales_model_service_quote_submit_failuretry restarting transactionMagento\Sales\Model\Service\PaymentFailuresServiceto send an email highlighting that a successful order was rolled back because of deadlock. Allowing for prompt investigation and contacting of the customer.The above conditions should allow us to remove all false alerts and ensure this only fires during this scenario.
https://gist.github.com/convenient/ea1411d650e8765278338adc36deba93
Next steps
Can anyone from Magento advise on what could be causing the deadlock on the
sales_invoicetable? How to solve this issue properly?I got the same issue on 2.4.2, anyone know how to fix it?
Everything we’ve done so far which have eliminated deadlocks occuring during orders and greatly reduced deadlocks overall:
In Magento: Asynchronous grid = on Flat products and categories = on Async indexing = on Production mode enabled always Install Cadence_DeadlockRetry
In my.cnf transaction-isolation = READ-COMMITTED (along with other optimizations)
Beef up your server’s CPU and disk speed (IOPS) as much as possible. This is very important, even for low traffic sites. Fast SSD’s on dedicated hardware/instances are a must.
Switched to authorize.net for CC orders (mainly due to double auth fees with the payflow integration) - see https://github.com/magento/magento2/issues/6542 - no more missing CC orders either.
At this point we aren’t seeing any order related mysql deadlocks, but we are still seeing very occasional “wrong order ID” in the system log and a corresponding missing paypal order. What gives?
We determined this remaining issue is poor CURL error handling in the payflow module. A VERY occasional connection issue with paypal with no attempt to retry and no traceback thrown. If this happens during order processing after the first API call (several API calls are made) you are left with a missing/incomplete order. You’ll have a payment, a quote with valid order ID, but no corresponding order.
We wrote a command line module to programatically complete these orders. We could even take it one step further and grep the exception log for "Wrong order ID: “$n” and automate it.
Ideally, there should at least be N retries when CURL exceptions occur (similar to what the Cadence_DeadlockRetry module does for mysql deadlocks). We briefly attempted this but found magento’s payflow integration too dense and co-dependant with other core modules to override completely.
;TLDR
This entire issue has at least two causes. MySQL deadlocks which are a way of life with magento, and poor exception handling in the payflow module. Neither of these issues are trivial to expose in testing, so the devs are not going to spend time with this.
The payflow integration in it’s current state across all magento2 versions is a steaming pile. Switch to something else for payments (at least for CC’s), if you can.
I have confirmed that this is happening on Magento 2.2.6. A small number of orders have captured funds, but the order has not been created. I get the following in exception.log:
[2018-10-26 11:56:00] report.CRITICAL: Wrong order ID: "XXXXXXXXXX". {"exception":"[object] (Exception(code: 0): Wrong order ID: \"XXXXXXXXXX\". at /path/to/vendor/magento/module-paypal/Model/Ipn.php:140)"} []This issue comes from your third-party module. Kindly re-check all your module which customized the order flow. I fixed it with condition check Order Object in Observer.
if ( $order )@engcom-backlog-nazar Thank you for verifying the issue. Based on the provided information internal tickets
MAGETWO-97869,MAGETWO-97870were createdHi @djamps Would you mind sharing your command line module to complete the missing orders? Would be greatly appreciated!
Wow. @magento-engcom-team I know this is hard to reproduce but didn’t my steps at least provide something for you to work with ?
Having the same issue on the latest Magento version 2.4.5-p1. I recently upgraded magento from 2.4.1 to 2.4.5-p1, and made some test orders, then the issue happened occasionally. Unfortunately I can not reproduce it, but I can provide some details for solving this problem. The system log as following:
Magento system is writing the same error for the order ID 000000434 again and again, but actually it has created the order ID 000000435 for this transaction. In my papal account, the order ID for the transaction is 000000434, magento 000000435 for the same transaction number instead. So the problem is that order ids in magento and paypal for the transaction should be same, but different instead. I think wrong order ID passed to paypal system, then it sends the IPN with wrong order ID again and again.
At the same time, the issue seems be related to the paypal express review step, when you make the payment using paypal express checkout on product or shopping cart page, you login your paypal account, click continue, it should be redirected to the paypal/express/review page, but for the order with this error, I remember, the order was placed directly, your are redirected to the suscess page without review step, and the shopping cart was not cleared after purchase.
Since I’m not a professional programmer, hope this will help for the issue.
It even happening in Magento 2.4.3.
I have confirmed that this is happening on Magento 2.3.7!
Having same issue in 2.3.2
hi @convenient Thank you for your detailed explanation.