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)"}
Hi @BezV8 i cannot reproduce by your scenario, i have order registered in magento.
Noticed the same issue on a CE 2.2.5 system...
@engcom-backlog-nazar Apologies for the delay in responding to this. I have not noticed a recurrence of this issue for some time now, so it ay have sorted itself out. It looks like others (gewaechshaus) may also be experiencing a similar problem.
Yes, actually we got 3-5 orders where it did happen . Currently we can't log the issue,
Hi @gewaechshaus Can you provide steps to reproduce ? or can you reproduce on vanilla instance ?
@BezV8 , we are closing this issue due to inactivity. If you'd like to update it, please reopen the issue.
We are seeing a similar issue but no order id in the logs. This is on 2.2.3
[2018-09-05 20:13:12] report.CRITICAL: Wrong order ID: "". {"exception":"[object] (Exception(code: 0): Wrong order ID: \"\". at vendor/magento/module-paypal/Model/Ipn.php:140)"} []
I'm also seeing this in 2.2.3 open source;
[] main.CRITICAL: Wrong order ID: "000004793". {"exception":"[object] (Exception(code: 0): Wrong order ID: \"000004793\". at /home/panel/htdocs/somesite/vendor/magento/module-paypal/Model/Ipn.php:140)"} []
HI @karlsminton Can You describe how you get this error? to help us reproduce this issue?
Same here.
My Magento version 2.1.9.
I've seen this today. 2.1.7.
Hi @engcom-backlog-nazar - I've literally just inherited this so I've not got many ideas about how to reproduce it. I can confirm though, that it's taking orders correctly +99% of the time, but we've had some reports of customers orders failing inexplicably.
According to our client, the paypal payment failed - but the order confirmation was sent.
Hi @BezV8 Hi @karlsminton I'm reopen this as many people have this issue.
I've been debugging this all day, using both the apache logs of an affected user and xdebug locally to understand the request flow.
I believe I have the beginnings of a theory as to whats happening, although I haven't worked it all out yet.
I believe the Skip Order Review Page
setting may be relevant, we have it set to Yes
When I viewed the apache access logs that corresponded to the broken order I found requests like the following.
GET /uk/paypal/express/start/ - 302
GET /uk/paypal/express/return?token=FOO&PayerID=BAR - 302
GET /uk/paypal/express/review/ - 200
POST /uk/paypal/express/placeOrder/ - 302
GET /uk/paypal/express/review/ - 200
We should never be hitting review, but that's what we're seeing. I read through the code and replicated similar behaviour locally by hacking in a bad response from paypal. It seems there is some error handling in the module that will redirect to the review page in the event of an error.
This code is placed within PlaceOrder as a successful call to the return action will call $this->_forward('placeOrder')
.
# https://github.com/magento/magento2/blob/2.1.15/app/code/Magento/Paypal/Controller/Express/AbstractExpress/PlaceOrder.php#L93
try {
+ throw new ApiProcessableException(
+ new \Magento\Framework\Phrase('mock api failure'),
+ new \Exception(),
+ 10736
+ );
$this->_initCheckout();
$this->_checkout->place($this->_initToken());
// prepare session to success or cancellation page
$this->_getCheckoutSession()->clearHelperData();
This exception gets picked up by this line of code
https://github.com/magento/magento2/blob/2.1.15/app/code/Magento/Paypal/Controller/Express/AbstractExpress/PlaceOrder.php#L128-L129
Which is processed by
https://github.com/magento/magento2/blob/2.1.15/app/code/Magento/Paypal/Controller/Express/AbstractExpress/PlaceOrder.php#L159-L161
Which simply outputs the error but doesn't log it before redirecting to the review page (which we skip in usual flow)
https://github.com/magento/magento2/blob/2.1.15/app/code/Magento/Paypal/Controller/Express/AbstractExpress/PlaceOrder.php#L209-L212
By placing a paypal order with the above exception in place I am left with
reserved_order_id
When the customer retried to placeorder
by hitting the button on the page they were returned to the review page again, likely due to whatever unlogged API error occurred.
We did not intend the paypal review page to be viewable on our site so it was not fully styled and the customer may miss the session messaging.
Problems with this theory
Anyway it's been a long day debugging, but here's my notes anyway.
Confirmed, issue on Magento 2.2.5
magento.CRITICAL: Wrong order ID: "XXXXXXXX". {"exception":"[object] (Exception(code: 0): Wrong order ID: \"XXXXXXXX\". at /path/to/vendor/magento/module-paypal/Model/Ipn.php:140)"} {"url":"/paypal/ipn/","ip":"XXXXXXXX","http_method":"POST","server":"XXXXXXXX","referrer":null}
@convenient Thank you for the detailed logging! Have you managed to get any further debugging the issue since your previous comment?
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)"} []
Same issue here. As I imported old command with home made script from magento1 instance is there any possibility that this is related to a bad increment id sequence ? Because orders from magento1 don't have the same store id and the increment_id pattern does not correspond to the new magento2 website. But for other payment method I do not have any issues.
Also can it be related to guest order ?
So question or all of those that have this issue : does this happen only for guest orders ? Could it be related to sequence number / tables ?
As @dewayneholden said, paypal capture the paiement but does not create the associated order / invoice.
Hi,
same on 2.1.15. Bunch of "Wrong order ID" errors in exception.log
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_invoice
which caused the order to be rolled back which reverts the valid sales_order
entry. paypal/express/review
with the session message We can't place the order
where they can attempt to press Place Order
again.PayPal gateway has rejected request. A successful transaction has already been completed for this token
exception will be logged.Explanation of how I found this, and my mitigation.
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.)
--- Controller/Express/AbstractExpress/PlaceOrder.php 2018-11-23 15:32:32.000000000 +0000
+++ Controller/Express/AbstractExpress/PlaceOrder.php 2018-11-23 15:31:53.000000000 +0000
@@ -27,6 +27,17 @@
private $paymentFailures;
/**
+ * Logger added to debug JIRA-TICKET-123
+ *
+ * Paypal order auth and captured with no corresponding order in magento.
+ *
+ * @var \Psr\Log\LoggerInterface
+ *
+ * @author Luke Rodgers
+ */
+ protected $logger;
+
+ /**
* @param \Magento\Framework\App\Action\Context $context
* @param \Magento\Customer\Model\Session $customerSession
* @param \Magento\Checkout\Model\Session $checkoutSession
@@ -49,9 +60,11 @@
\Magento\Framework\Url\Helper\Data $urlHelper,
\Magento\Customer\Model\Url $customerUrl,
\Magento\Checkout\Api\AgreementsValidatorInterface $agreementValidator,
+ \Psr\Log\LoggerInterface $logger,
PaymentFailuresInterface $paymentFailures = null
) {
$this->agreementsValidator = $agreementValidator;
+ $this->logger = $logger;
$this->paymentFailures = $paymentFailures ? : ObjectManager::getInstance()
->get(PaymentFailuresInterface::class);
@@ -126,8 +139,12 @@
$this->_redirect('checkout/onepage/success');
return;
} catch (ApiProcessableException $e) {
+ $this->logger->critical("Logging for JIRA-TICKET-123");
+ $this->logger->critical($e);
$this->_processPaypalApiError($e);
} catch (\Exception $e) {
+ $this->logger->critical("Logging for JIRA-TICKET-123");
+ $this->logger->critical($e);
$this->messageManager->addExceptionMessage(
$e,
__('We can\'t place the order.')
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_id
which we need to proceed.
select entity_id, created_at, updated_at, remote_ip, reserved_order_id from quote
where reserved_order_id='XX123456789';
This will give you the updated_at
time, this and the remote_ip
can also be used to cross reference with your apache logs to confirm the user journey and that the customer ended up on paypal/express/review
.
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 quote updated_at
field.
[2018-12-29 00:01:04] report.CRITICAL: Logging for JIRA-TICKET-123 [] []
[2018-12-29 00:01:04] report.CRITICAL: Exception message: SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction, query was: INSERT INTO `sales_invoice` (`store_id`, `base_grand_total`, `shipping_tax_amount`, `tax_amount`, `base_tax_amount`, `store_to_order_rate`, `base_shipping_tax_amount`, `base_discount_amount`, `base_to_order_rate`, `grand_total`, `shipping_amount`, `subtotal_incl_tax`, `base_subtotal_incl_tax`, `store_to_base_rate`, `base_shipping_amount`, `total_qty`, `base_to_global_rate`, `subtotal`, `base_subtotal`, `discount_amount`, `billing_address_id`, `order_id`, `state`, `shipping_address_id`, `store_currency_code`, `transaction_id`, `order_currency_code`, `base_currency_code`, `global_currency_code`, `increment_id`, `discount_tax_compensation_amount`, `base_discount_tax_compensation_amount`, `shipping_discount_tax_compensation_amount`, `base_shipping_discount_tax_compensation_amnt`, `discount_description`) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
Trace: #0 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/DB/Statement/Pdo/Mysql.php(95): Zend_Db_Statement_Pdo->_execute(Array)
#1 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/zendframework1/library/Zend/Db/Statement.php(303): Magento\Framework\DB\Statement\Pdo\Mysql->_execute(Array)
#2 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/zendframework1/library/Zend/Db/Adapter/Abstract.php(480): Zend_Db_Statement->execute(Array)
#3 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/zendframework1/library/Zend/Db/Adapter/Pdo/Abstract.php(238): Zend_Db_Adapter_Abstract->query('INSERT INTO `sa...', Array)
#4 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/DB/Adapter/Pdo/Mysql.php(465): Zend_Db_Adapter_Pdo_Abstract->query('INSERT INTO `sa...', Array)
#5 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/DB/Adapter/Pdo/Mysql.php(520): Magento\Framework\DB\Adapter\Pdo\Mysql->_query('INSERT INTO `sa...', Array)
#6 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/zendframework1/library/Zend/Db/Adapter/Abstract.php(576): Magento\Framework\DB\Adapter\Pdo\Mysql->query('INSERT INTO `sa...', Array)
#7 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/module-sales/Model/ResourceModel/EntityAbstract.php(185): Zend_Db_Adapter_Abstract->insert('sales_invoice', Array)
#8 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Model/ResourceModel/Db/AbstractDb.php(405): Magento\Sales\Model\ResourceModel\EntityAbstract->saveNewObject(Object(Magento\Sales\Model\Order\Invoice))
#9 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Model/AbstractModel.php(636): Magento\Framework\Model\ResourceModel\Db\AbstractDb->save(Object(Magento\Sales\Model\Order\Invoice))
#10 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/module-sales/Model/ResourceModel/Order/Relation.php(95): Magento\Framework\Model\AbstractModel->save()
#11 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Model/ResourceModel/Db/VersionControl/RelationComposite.php(48): Magento\Sales\Model\ResourceModel\Order\Relation->processRelation(Object(Magento\Sales\Model\Order\Interceptor))
#12 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Model/ResourceModel/Db/VersionControl/AbstractDb.php(57): Magento\Framework\Model\ResourceModel\Db\VersionControl\RelationComposite->processRelations(Object(Magento\Sales\Model\Order\Interceptor))
#13 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Model/ResourceModel/Db/AbstractDb.php(408): Magento\Framework\Model\ResourceModel\Db\VersionControl\AbstractDb->processAfterSaves(Object(Magento\Sales\Model\Order\Interceptor))
#14 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/module-sales/Model/ResourceModel/Order.php(178): Magento\Framework\Model\ResourceModel\Db\AbstractDb->save(Object(Magento\Sales\Model\Order\Interceptor))
#15 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/module-sales/Model/OrderRepository.php(161): Magento\Sales\Model\ResourceModel\Order->save(Object(Magento\Sales\Model\Order\Interceptor))
#16 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Interception/Interceptor.php(146): Magento\Sales\Model\OrderRepository->save(Object(Magento\Sales\Model\Order\Interceptor))
#17 /var/www/vhosts/example.com/production/releases/1545033608/var/generation/Magento/Sales/Model/OrderRepository/Interceptor.php(52): Magento\Sales\Model\OrderRepository\Interceptor->___callPlugins('save', Array, Array)
#18 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/module-sales/Model/Service/OrderService.php(202): Magento\Sales\Model\OrderRepository\Interceptor->save(Object(Magento\Sales\Model\Order\Interceptor))
#19 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/module-quote/Model/QuoteManagement.php(499): Magento\Sales\Model\Service\OrderService->place(Object(Magento\Sales\Model\Order\Interceptor))
#20 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/module-quote/Model/QuoteManagement.php(395): Magento\Quote\Model\QuoteManagement->submitQuote(Object(Magento\Quote\Model\Quote\Interceptor), Array)
#21 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/module-paypal/Model/Express/Checkout.php(799): Magento\Quote\Model\QuoteManagement->submit(Object(Magento\Quote\Model\Quote\Interceptor))
#22 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/module-paypal/Controller/Express/AbstractExpress/PlaceOrder.php(107): Magento\Paypal\Model\Express\Checkout->place('AA-11A11111A111...')
#23 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/App/Action/Action.php(102): Magento\Paypal\Controller\Express\AbstractExpress\PlaceOrder->execute()
#24 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Interception/Interceptor.php(74): Magento\Framework\App\Action\Action->dispatch(Object(Magento\Framework\App\Request\Http))
#25 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Interception/Chain/Chain.php(70): Magento\Paypal\Controller\Express\PlaceOrder\Interceptor->___callParent('dispatch', Array)
#26 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Interception/Chain/Chain.php(63): Magento\Framework\Interception\Chain\Chain->invokeNext('Magento\\Paypal\\...', 'dispatch', Object(Magento\Paypal\Controller\Express\PlaceOrder\Interceptor), Array, 'contextPlugin')
#27 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/module-store/App/Action/Plugin/Context.php(106): Magento\Framework\Interception\Chain\Chain->Magento\Framework\Interception\Chain\{closure}(Object(Magento\Framework\App\Request\Http))
#28 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Interception/Chain/Chain.php(67): Magento\Store\App\Action\Plugin\Context->aroundDispatch(Object(Magento\Paypal\Controller\Express\PlaceOrder\Interceptor), Object(Closure), Object(Magento\Framework\App\Request\Http))
#29 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Interception/Chain/Chain.php(63): Magento\Framework\Interception\Chain\Chain->invokeNext('Magento\\Paypal\\...', 'dispatch', Object(Magento\Paypal\Controller\Express\PlaceOrder\Interceptor), Array, 'customer-segmen...')
#30 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/module-customer-segment/Model/App/Action/ContextPlugin.php(81): Magento\Framework\Interception\Chain\Chain->Magento\Framework\Interception\Chain\{closure}(Object(Magento\Framework\App\Request\Http))
#31 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Interception/Chain/Chain.php(67): Magento\CustomerSegment\Model\App\Action\ContextPlugin->aroundDispatch(Object(Magento\Paypal\Controller\Express\PlaceOrder\Interceptor), Object(Closure), Object(Magento\Framework\App\Request\Http))
#32 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Interception/Chain/Chain.php(63): Magento\Framework\Interception\Chain\Chain->invokeNext('Magento\\Paypal\\...', 'dispatch', Object(Magento\Paypal\Controller\Express\PlaceOrder\Interceptor), Array, 'customer-app-ac...')
#33 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/module-customer/Model/App/Action/ContextPlugin.php(61): Magento\Framework\Interception\Chain\Chain->Magento\Framework\Interception\Chain\{closure}(Object(Magento\Framework\App\Request\Http))
#34 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Interception/Chain/Chain.php(67): Magento\Customer\Model\App\Action\ContextPlugin->aroundDispatch(Object(Magento\Paypal\Controller\Express\PlaceOrder\Interceptor), Object(Closure), Object(Magento\Framework\App\Request\Http))
#35 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Interception/Chain/Chain.php(63): Magento\Framework\Interception\Chain\Chain->invokeNext('Magento\\Paypal\\...', 'dispatch', Object(Magento\Paypal\Controller\Express\PlaceOrder\Interceptor), Array, 'storeCheck')
#36 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/module-store/App/Action/Plugin/StoreCheck.php(44): Magento\Framework\Interception\Chain\Chain->Magento\Framework\Interception\Chain\{closure}(Object(Magento\Framework\App\Request\Http))
#37 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Interception/Chain/Chain.php(67): Magento\Store\App\Action\Plugin\StoreCheck->aroundDispatch(Object(Magento\Paypal\Controller\Express\PlaceOrder\Interceptor), Object(Closure), Object(Magento\Framework\App\Request\Http))
#38 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Interception/Chain/Chain.php(63): Magento\Framework\Interception\Chain\Chain->invokeNext('Magento\\Paypal\\...', 'dispatch', Object(Magento\Paypal\Controller\Express\PlaceOrder\Interceptor), Array, 'weee-app-action...')
#39 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/module-weee/Model/App/Action/ContextPlugin.php(112): Magento\Framework\Interception\Chain\Chain->Magento\Framework\Interception\Chain\{closure}(Object(Magento\Framework\App\Request\Http))
#40 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Interception/Chain/Chain.php(67): Magento\Weee\Model\App\Action\ContextPlugin->aroundDispatch(Object(Magento\Paypal\Controller\Express\PlaceOrder\Interceptor), Object(Closure), Object(Magento\Framework\App\Request\Http))
#41 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Interception/Interceptor.php(138): Magento\Framework\Interception\Chain\Chain->invokeNext('Magento\\Paypal\\...', 'dispatch', Object(Magento\Paypal\Controller\Express\PlaceOrder\Interceptor), Array, 'tax-app-action-...')
#42 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/module-tax/Model/App/Action/ContextPlugin.php(91): Magento\Paypal\Controller\Express\PlaceOrder\Interceptor->Magento\Framework\Interception\{closure}(Object(Magento\Framework\App\Request\Http))
#43 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Interception/Interceptor.php(142): Magento\Tax\Model\App\Action\ContextPlugin->aroundDispatch(Object(Magento\Paypal\Controller\Express\PlaceOrder\Interceptor), Object(Closure), Object(Magento\Framework\App\Request\Http))
#44 /var/www/vhosts/example.com/production/releases/1545033608/var/generation/Magento/Paypal/Controller/Express/PlaceOrder/Interceptor.php(26): Magento\Paypal\Controller\Express\PlaceOrder\Interceptor->___callPlugins('dispatch', Array, Array)
#45 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/App/FrontController.php(55): Magento\Paypal\Controller\Express\PlaceOrder\Interceptor->dispatch(Object(Magento\Framework\App\Request\Http))
#46 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Interception/Interceptor.php(74): Magento\Framework\App\FrontController->dispatch(Object(Magento\Framework\App\Request\Http))
#47 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Interception/Chain/Chain.php(70): Magento\Framework\App\FrontController\Interceptor->___callParent('dispatch', Array)
#48 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Interception/Chain/Chain.php(63): Magento\Framework\Interception\Chain\Chain->invokeNext('Magento\\Framewo...', 'dispatch', Object(Magento\Framework\App\FrontController\Interceptor), Array, 'requestPreproce...')
#49 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/module-store/App/FrontController/Plugin/RequestPreprocessor.php(94): Magento\Framework\Interception\Chain\Chain->Magento\Framework\Interception\Chain\{closure}(Object(Magento\Framework\App\Request\Http))
#50 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Interception/Chain/Chain.php(67): Magento\Store\App\FrontController\Plugin\RequestPreprocessor->aroundDispatch(Object(Magento\Framework\App\FrontController\Interceptor), Object(Closure), Object(Magento\Framework\App\Request\Http))
#51 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Interception/Chain/Chain.php(63): Magento\Framework\Interception\Chain\Chain->invokeNext('Magento\\Framewo...', 'dispatch', Object(Magento\Framework\App\FrontController\Interceptor), Array, 'install')
#52 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Module/Plugin/DbStatusValidator.php(69): Magento\Framework\Interception\Chain\Chain->Magento\Framework\Interception\Chain\{closure}(Object(Magento\Framework\App\Request\Http))
#53 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Interception/Chain/Chain.php(67): Magento\Framework\Module\Plugin\DbStatusValidator->aroundDispatch(Object(Magento\Framework\App\FrontController\Interceptor), Object(Closure), Object(Magento\Framework\App\Request\Http))
#54 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Interception/Chain/Chain.php(63): Magento\Framework\Interception\Chain\Chain->invokeNext('Magento\\Framewo...', 'dispatch', Object(Magento\Framework\App\FrontController\Interceptor), Array, 'front-controlle...')
#55 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/module-page-cache/Model/App/FrontController/VarnishPlugin.php(55): Magento\Framework\Interception\Chain\Chain->Magento\Framework\Interception\Chain\{closure}(Object(Magento\Framework\App\Request\Http))
#56 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Interception/Chain/Chain.php(67): Magento\PageCache\Model\App\FrontController\VarnishPlugin->aroundDispatch(Object(Magento\Framework\App\FrontController\Interceptor), Object(Closure), Object(Magento\Framework\App\Request\Http))
#57 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Interception/Interceptor.php(138): Magento\Framework\Interception\Chain\Chain->invokeNext('Magento\\Framewo...', 'dispatch', Object(Magento\Framework\App\FrontController\Interceptor), Array, 'front-controlle...')
#58 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/module-page-cache/Model/App/FrontController/BuiltinPlugin.php(69): Magento\Framework\App\FrontController\Interceptor->Magento\Framework\Interception\{closure}(Object(Magento\Framework\App\Request\Http))
#59 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/Interception/Interceptor.php(142): Magento\PageCache\Model\App\FrontController\BuiltinPlugin->aroundDispatch(Object(Magento\Framework\App\FrontController\Interceptor), Object(Closure), Object(Magento\Framework\App\Request\Http))
#60 /var/www/vhosts/example.com/production/releases/1545033608/var/generation/Magento/Framework/App/FrontController/Interceptor.php(26): Magento\Framework\App\FrontController\Interceptor->___callPlugins('dispatch', Array, Array)
#61 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/App/Http.php(135): Magento\Framework\App\FrontController\Interceptor->dispatch(Object(Magento\Framework\App\Request\Http))
#62 /var/www/vhosts/example.com/production/releases/1545033608/vendor/magento/framework/App/Bootstrap.php(258): Magento\Framework\App\Http->launch()
#63 /var/www/vhosts/example.com/production/releases/1545033608/pub/index.php(37): Magento\Framework\App\Bootstrap->run(Object(Magento\Framework\App\Http))
#64 {main} [] []
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!
payment/paypal_express/payment_action
is set to Sale
so that invoices are created when the payment is processed.Prepare to lock the sales_invoice
table by getting the next values
# Get the next order entity_id
$ magerun2 db:query 'select max(entity_id)+1 as next_order_id from sales_order'
next_order_id
10
# Get the next invoice increment_id
$ magerun2 db:query 'select increment_id+1 as next_increment_id from sales_invoice order by entity_id desc limit 1'
next_increment_id
2000006607
# Get the id for your given store view
$ magerun2 sys:store:list | grep uk
| 2 | uk |
Open 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.
BEGIN;
insert into sales_order(entity_id, store_id) values (10, 2);
insert into sales_invoice(order_id, increment_id, store_id) values (10, '2000006607', 2);
Proceed through the paypal checkout process. The callback to Magento should fail and take you to paypal/express/review
where you cannot progress from. This order is broken.
Close your database terminal to release the lock without writing.
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_failure
try restarting transaction
Magento\Sales\Model\Service\PaymentFailuresService
to 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.
Can anyone from Magento advise on what could be causing the deadlock on the sales_invoice
table? How to solve this issue properly?
@engcom-backlog-nazar Thank you for verifying the issue. Based on the provided information internal tickets MAGETWO-97869
, MAGETWO-97870
were created
hi @convenient Thank you for your detailed explanation.
@engcom-backlog-nazar
any update on this issue?, any workarounds available?
verified on 2.3.0. Please advise on how to solve this.
Same issue on 2.3.0.
[2019-03-31 16:27:48] main.CRITICAL: Wrong order ID: "XXXXXX2351". {"exception":"[object] (Exception(code: 0): Wrong order ID: "XXXXXX2351". at /var/www/html/vendor/magento/module-paypal/Model/Ipn.php:140)"} []
Have someone got any fix to this? I am also facing the same problem in Magento 2.2.7.
We are running into this issue constantly and its super important we get this fixed. I cannot believe how old this issue is and we still don't have a fix.
Any update on the situation?
Same issue 2.2.8
Same issue 2.3.1, Any updates available so far?
Same issue 2.3.1, customers complaining as orders are being missed. Any update on this bug?
We're also observing that issue on 2.3.1 - lot's of _The "" order ID is incorrect_ messages, some have a number, but most don't:
main.CRITICAL: The "XXXXXXXXX" order ID is incorrect. Verify the ID and try again. {"exception":"[object] (Exception(code: 0): The \"XXXXXXXXX\" order ID is incorrect. Verify the ID and try again. at /var/www/vhosts/mage_root/vendor/magento/module-paypal/Model/Ipn.php:143)"} []
main.CRITICAL: The "" order ID is incorrect. Verify the ID and try again. {"exception":"[object] (Exception(code: 0): The \"\" order ID is incorrect. Verify the ID and try again. at /var/www/vhosts/mage_root/vendor/magento/module-paypal/Model/Ipn.php:143)"} []
Same issue since upgrade to 2.3.1 (single store mode). There are 7 missing and 2 registered PayPal payments in Magento in 11 days.
Missing orders are recurring in exception log as
[2019-06-05 20:47:44] main.CRITICAL: The "0000XXXXX" order ID is incorrect. Verify the ID and try again. {"exception":"[object] (Exception(code: 0): The \"0000XXXXX\" order ID is incorrect. Verify the ID and try again. at /vendor/magento/module-paypal/Model/Ipn.php:143)"} []
[2019-06-05 20:48:05] main.CRITICAL: The "" order ID is incorrect. Verify the ID and try again. {"exception":"[object] (Exception(code: 0): The \"\" order ID is incorrect. Verify the ID and try again. at /vendor/magento/module-paypal/Model/Ipn.php:143)"} []
[2019-06-05 20:48:25] main.CRITICAL: The "" order ID is incorrect. Verify the ID and try again. {"exception":"[object] (Exception(code: 0): The \"\" order ID is incorrect. Verify the ID and try again. at /vendor/magento/module-paypal/Model/Ipn.php:143)"} []
[2019-06-05 20:48:45] main.CRITICAL: The "" order ID is incorrect. Verify the ID and try again. {"exception":"[object] (Exception(code: 0): The \"\" order ID is incorrect. Verify the ID and try again. at /vendor/magento/module-paypal/Model/Ipn.php:143)"} []
[2019-06-05 20:49:05] main.CRITICAL: The "" order ID is incorrect. Verify the ID and try again. {"exception":"[object] (Exception(code: 0): The \"\" order ID is incorrect. Verify the ID and try again. at /vendor/magento/module-paypal/Model/Ipn.php:143)"} []
@engcom-backlog-nazar Any updates? This is causing big issues for our client. Many orders being missed...
Yes, all of our clients have the same issue. It would be highly appreciated to have some response.
Hi @BezV8.
Thank you for your report and collaboration!
The related internal Jira ticket MAGETWO-97869
was closed as non-reproducible
in 2.2.x
.
It means that Magento team either unable to reproduce this issue using provided _Steps to Reproduce_ from the _Description section_ on clean or the issue has been already fixed in the scope of other tasks.
But if you still run into this problem please update or provide additional information/steps/preconditions in the _Description section_ and reopen this issue.
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 ?
@magento-engcom-team Has this been closed due to a fix in 2.3.2?
@magento-engcom-team Also seeing this in 2.3.1, can I get an update ASAP please?
@magento-engcom-team Clearly there is an issue here. Very disappointed too see you punting this issue b/c you cannot get a solid repro even after all the time and feedback that has been invested by the community.
I can confirm this issue in 2.3
I'm seeing this in 2.3.1
Hey @all, Hey @convenient ,
we are currently facing this issue on every order in a customers MOS 2.2.8 system, as soon as we configure the action to "sale" instead of "authorization".
Edit: We found out that this is related to a custom sequence which shortes the order id from 10 to 9 digits.
Hi all,
Magento support have highlighted the following as fixing this issue..
https://github.com/magento/magento2/commit/547f45390b5056dae75e42987856f05e4ec3cbc9
@magento-engcom-team what release line is this going to be tagged in please?
Hey @magento-engcom-team,
We are seeing this in a fairly high percentage of orders for us, is there an internal ticket I can take a look at for this?
2.2.9 affected
Still seeing this issue even after applying the patch I linked.
@gewaechshaus did you mean it is because of customizing the Order increment ID? if so how can we solve this issue after adjusting the increment ID using below update via di.xml as below?
<type name="Magento\Framework\DB\Sequence\SequenceInterface">
<arguments>
<argument name="pattern" xsi:type="string">%s%'.04d%s</argument>
</arguments>
</type>
As I don't see this is related only to PayPal (because it is the one which records the missing record) however we have a bank transfer payment which is not even recorded anywhere in Magento
We're getting this issue about 1 out of 500 orders more or less. Every few days for us.
We were getting similar issue in M1 for years and hoped that M2 would resolve it, apparently not.
What is everyone's setting for Asynchronous grid?
Better or worse with async grid = on?
Having this issue on 2.3.0 for all orders
Can confirm the problem for 2.3.1 on all Paypal orders.
Can confirm the problem for 2.3.1 on all Paypal orders.
As it turned out for us, the problem was not in the Magento code. We have a custom payment method with an observer listening to the sales_order_payment_save_before event. In the observer we Injected an instance of Magento\Webapi\Controller\Rest\InputParamsResolver and called its resolve method without checking if the route name is empty. If the route name is not empty this causes an exception, because the route could not be found, but this exception was somehow not logged. We added an additional check for a non-empty route name and now the Paypal problem doesn't occur anymore.
Hope this might be helpful for someone having a similar problem.
Having same issue in 2.3.2
Same here in 2.3.2, is there anyone working on this @magento-engcom-team as this is also affecting the payflo pro as well.
Hi all,
Magento support have highlighted the following as fixing this issue..
547f453@magento-engcom-team what release line is this going to be tagged in please?
@craigcarnell did this work for you?
@magento-team Any update on this issue?
So far no solution here. In the mean time had to disable PayPal express, and offer only credit card payments,
store- configuration- sales- payment method / payment pro- configure / PayPal express checkout-Advance Setting) Payment applicable from specific countries, and no countries selected.
@shauldover does this only affect Paypal Express or all forms of paypal (e/g credit cards on your site via payflow/payments pro)? Due to the nature of the issue (DB deadlocks) it would surprise me if this issue is specific to any payment method.
@djamps Only PayPal Express. Credit card through payflow working fine.
Same issue here
confirmed on 2.2.8
Any updates?
I'm having the same issue in Magento 2.3.2 using PayPal Standard. PayPal is sending client notifications that "
Please check your server that handles PayPal Instant Payment Notifications (IPN). IPNs sent to the following URL(s) are failing:"
im migrating all my magento client from magento. this platform is ridiculously poor and a money pit of a platform. Good luck!
We haven't gotten a DB deadlock on orders in over a month since doing two things (not sure which is more affective).
We still get an occational deadlock on the cron process but this is small potatos compared to orders failing. I recommend the following module to help in some of these cases:
https://github.com/cadencelabs/magento2-deadlockRetry
However, we still have get occasional uncaptured/missing paypal express orders (wrong order ID in log, ect). With no evidence of deadlock, it turns out these are all international orders and the failure is triggered by a missing state/province in the customer's paypal account.
Does anyone have any solution to fix this error?
Apparently not.
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 )
The solution is to store guest data in a timely manner:
module-checkout/Model/GuestPaymentInformationManagement.php
public function savePaymentInformation(
$cartId,
$email,
\Magento\Quote\Api\Data\PaymentInterface $paymentMethod,
\Magento\Quote\Api\Data\AddressInterface $billingAddress = null
) {
$quoteIdMask = $this->quoteIdMaskFactory->create()->load($cartId, 'masked_id');
/** @var Quote $quote */
$quote = $this->cartRepository->getActive($quoteIdMask->getQuoteId());
if ($billingAddress) {
$billingAddress->setEmail($email);
$quote->removeAddress($quote->getBillingAddress()->getId());
$quote->setBillingAddress($billingAddress);
$quote->setCustomerEmail($email);
$quote->setDataChanges(true);
} else {
$quote->getBillingAddress()->setEmail($email);
}
$this->cartRepository->save($quote);
$this->limitShippingCarrier($quote);
$this->cartRepository->save($quote);
$this->paymentMethodManagement->set($cartId, $paymentMethod);
return true;
}
I think this would be the correct patch for 2.3.0 (all credits to @olgaiskra):
--- clean/GuestPaymentInformationManagement.php 2019-09-20 14:25:56.696734848 +0200
+++ new/GuestPaymentInformationManagement.php 2019-09-23 08:48:37.286939940 +0200
@@ -137,6 +137,7 @@
\Magento\Quote\Api\Data\PaymentInterface $paymentMethod,
\Magento\Quote\Api\Data\AddressInterface $billingAddress = null
) {
+ //O Romanovskaja Agenda 20.09.2019 changed for Pay Pal Guest working
$quoteIdMask = $this->quoteIdMaskFactory->create()->load($cartId, 'masked_id');
/** @var Quote $quote */
$quote = $this->cartRepository->getActive($quoteIdMask->getQuoteId());
@@ -145,12 +146,14 @@
$billingAddress->setEmail($email);
$quote->removeAddress($quote->getBillingAddress()->getId());
$quote->setBillingAddress($billingAddress);
+ $quote->setCustomerEmail($email);
$quote->setDataChanges(true);
} else {
$quote->getBillingAddress()->setEmail($email);
}
$this->limitShippingCarrier($quote);
-
+ $this->cartRepository->save($quote);
+
$this->paymentMethodManagement->set($cartId, $paymentMethod);
return true;
}
Hi,
Has anyone found the solution for this issue?
Thanks
If this issue is severe enough for developers to create extensions to mitigate the effects, why hasn't this been resolved? Very frustrating.
yes, this is a painful one. I also facing it on a 2.3.3 version.
Seeing this on multiple installations of Magento 2.3.3. Tried all the above fixes an none of them appear to fix the issue.
Problem also exists on Magento 2.3.2.
error...
main.CRITICAL: The "10000003523" order ID is incorrect. Verify the ID and try again. {"exception":"[object] (Exception(code: 0): The \"10000003523\" order ID is incorrect. Verify the ID and try again. at /home/xxx/public_html/vendor/magento/module-paypal/Model/Ipn.php:143)"} []
Problem also exists on Magento 2.3.2.
error...
main.CRITICAL: The "10000003523" order ID is incorrect. Verify the ID and try again. {"exception":"[object] (Exception(code: 0): The "10000003523" order ID is incorrect. Verify the ID and try again. at /home/xxx/public_html/vendor/magento/module-paypal/Model/Ipn.php:143)"} []
Exactly the same issue on our Magento 2.3.1 instance. It seems to happen randomly.
Found out that if any module intercepts this method
\Magento\Sales\Model\Order\Payment\State\CommandInterface::execute
and when that plugin failed then order is not placed in magento.
What interesting that, $order->getId()
in that method returns null
that's why some 3rd extensions can fail can cause this issue.
For some reason 3rd module can intercept any of this class instead of the interface
\Magento\Sales\Model\Order\Payment\State\RegisterCaptureNotificationCommand
\Magento\Sales\Model\Order\Payment\State\AuthorizeCommand
\Magento\Sales\Model\Order\Payment\State\CaptureCommand
\Magento\Sales\Model\Order\Payment\State\OrderCommand
UPD:
you can try to restore those orders based on saved quotes for them if there enough data,
here is SQL
SELECT DISTINCT quote.entity_id as quote_id, reserved_order_id, quote.store_id as store_id, quote.created_at, ord.entity_id
FROM quote
inner join quote_item item on quote.entity_id = item.quote_id and quote.reserved_order_id IS NOT NULL
inner join quote_payment payment on quote.entity_id = payment.quote_id and payment.method = 'paypal_express' and
payment.additional_information like '%paypal_express_checkout_token%'
left join sales_order as ord on ord.quote_id = quote.entity_id
where ord.entity_id is null;
can be related ? https://github.com/magento/magento2/issues/25862
Although that previously we thought it is only related to PayPal Express payment only and we disabled it, it it showing now also on credit card payment (PayPal pro). not on every order.
Anyone got possible fix?
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.
Hi @djamps
Would you mind sharing your command line module to complete the missing orders? Would be greatly appreciated!
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.
Hey
So I use 2.3.5-p1 and something like this happens. I just can't understand one thing, I use massiveGRID so I easily do a environment clone, change the url and it's working as a test one. The curious thing is that in live site this happens, all the info appears in quote tables but the order itself is not created at all, but, in the clone environment all works fine.
So I thought of 2 option or it was cloudflare or all the customers online that gives more load. With this I paused cloudflare, all kept the same, no order at all and the error. With the customers idk what to do, I installed Cadence_DeadlockRetry to see if it helped but no luck. I'm not sure if here it's the same cause but the errors surely is.
Anyone got news on this?
Thanks
In my case, after some hours debug and check files debug.log, exception.log, payment.log, I found the issue is Numeric value out of range: 167 Out of range value for column 'sequence_value' at row 1, query was: INSERT INTO
sequence_invoice_1() VALUES ()
Then I go to table sequence_invoice_1 and have changed type of "sequence_value" from int(10) to bigint(20). Now, it works fine.
Our customer have a lot order migration from Magento 1 to Magento 2. That is an issue. Hope it can help someone.
Alothemes - Happy Coding!
We have just had the issue on 2.3.5-p2:
[2020-11-12 12:35:51] main.CRITICAL: The "1000426282" order ID is incorrect. Verify the ID and try again. {"exception":"[object] (Exception(code: 0): The \"1000426282\" order ID is incorrect. Verify the ID and try again. at /vendor/magento/module-paypal/Model/Ipn.php:146)"} []
[2020-11-12 12:36:05] main.CRITICAL: The "1000426282" order ID is incorrect. Verify the ID and try again. {"exception":"[object] (Exception(code: 0): The \"1000426282\" order ID is incorrect. Verify the ID and try again. at /vendor/magento/module-paypal/Model/Ipn.php:146)"} []
[2020-11-12 12:36:26] main.CRITICAL: The "1000426282" order ID is incorrect. Verify the ID and try again. {"exception":"[object] (Exception(code: 0): The \"1000426282\" order ID is incorrect. Verify the ID and try again. at /vendor/magento/module-paypal/Model/Ipn.php:146)"} []
[2020-11-12 12:37:08] main.CRITICAL: The "1000426282" order ID is incorrect. Verify the ID and try again. {"exception":"[object] (Exception(code: 0): The \"1000426282\" order ID is incorrect. Verify the ID and try again. at /vendor/magento/module-paypal/Model/Ipn.php:146)"} []
[2020-11-12 12:38:30] main.CRITICAL: The "1000426282" order ID is incorrect. Verify the ID and try again. {"exception":"[object] (Exception(code: 0): The \"1000426282\" order ID is incorrect. Verify the ID and try again. at /vendor/magento/module-paypal/Model/Ipn.php:146)"} []
[2020-11-12 12:38:31] main.CRITICAL: The "1000426283" order ID is incorrect. Verify the ID and try again. {"exception":"[object] (Exception(code: 0): The \"1000426283\" order ID is incorrect. Verify the ID and try again. at /vendor/magento/module-paypal/Model/Ipn.php:146)"} []
[2020-11-12 12:38:33] main.CRITICAL: The "1000426283" order ID is incorrect. Verify the ID and try again. {"exception":"[object] (Exception(code: 0): The \"1000426283\" order ID is incorrect. Verify the ID and try again. at /vendor/magento/module-paypal/Model/Ipn.php:146)"} []
[2020-11-12 12:39:44] main.CRITICAL: The "1000426283" order ID is incorrect. Verify the ID and try again. {"exception":"[object] (Exception(code: 0): The \"1000426283\" order ID is incorrect. Verify the ID and try again. at /vendor/magento/module-paypal/Model/Ipn.php:146)"} []
[2020-11-12 12:40:36] main.CRITICAL: The "1000426284" order ID is incorrect. Verify the ID and try again. {"exception":"[object] (Exception(code: 0): The \"1000426284\" order ID is incorrect. Verify the ID and try again. at /vendor/magento/module-paypal/Model/Ipn.php:146)"} []
[2020-11-12 12:40:38] main.CRITICAL: The "1000426284" order ID is incorrect. Verify the ID and try again. {"exception":"[object] (Exception(code: 0): The \"1000426284\" order ID is incorrect. Verify the ID and try again. at /vendor/magento/module-paypal/Model/Ipn.php:146)"} []
[2020-11-12 12:40:49] main.CRITICAL: The "1000426284" order ID is incorrect. Verify the ID and try again. {"exception":"[object] (Exception(code: 0): The \"1000426284\" order ID is incorrect. Verify the ID and try again. at /vendor/magento/module-paypal/Model/Ipn.php:146)"} []
[2020-11-12 12:41:06] main.CRITICAL: The "1000426283" order ID is incorrect. Verify the ID and try again. {"exception":"[object] (Exception(code: 0): The \"1000426283\" order ID is incorrect. Verify the ID and try again. at /vendor/magento/module-paypal/Model/Ipn.php:146)"} []
[2020-11-12 12:41:12] main.CRITICAL: The "1000426284" order ID is incorrect. Verify the ID and try again. {"exception":"[object] (Exception(code: 0): The \"1000426284\" order ID is incorrect. Verify the ID and try again. at /vendor/magento/module-paypal/Model/Ipn.php:146)"} []
[2020-11-12 12:41:54] main.CRITICAL: The "1000426284" order ID is incorrect. Verify the ID and try again. {"exception":"[object] (Exception(code: 0): The \"1000426284\" order ID is incorrect. Verify the ID and try again. at /vendor/magento/module-paypal/Model/Ipn.php:146)"} []
Most helpful comment
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_invoice
which caused the order to be rolled back which reverts the validsales_order
entry.paypal/express/review
with the session messageWe can't place the order
where they can attempt to pressPlace Order
again.PayPal gateway has rejected request. A successful transaction has already been completed for this token
exception 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_id
which we need to proceed.Step 3 - Find the associated quote
This will give you the
updated_at
time, this and theremote_ip
can 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_at
field.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!
payment/paypal_express/payment_action
is set toSale
so that invoices are created when the payment is processed.Prepare to lock the
sales_invoice
table 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/review
where 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_failure
try restarting transaction
Magento\Sales\Model\Service\PaymentFailuresService
to 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.
Next steps
Can anyone from Magento advise on what could be causing the deadlock on the
sales_invoice
table? How to solve this issue properly?