Paypal some orders fail with main.CRITICAL: Wrong order ID:

[BezV8]

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

1. Magento 2.2.2
2. Paypal Express Checkout set as Payment method.

Steps to reproduce

1. Customer Places Order
2. Directed to PayPal page and payment taken
3. Redirected to site, order fails and is not logged in Magento.

Expected result

1. Once payment has been taken and the customer has been redirected back to the site order is registered with magento.

Actual result

1. Payment is taken.
2. Paypal redirects to site and sends confirmation email with correct order number.
3. Order is not registered in magento.
4. 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).

[ghost]

Hi @BezV8 i cannot reproduce by your scenario, i have order registered in magento.

[gewaechshaus]

Noticed the same issue on a CE 2.2.5 system...

[BezV8]

@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.

[gewaechshaus]

Yes, actually we got 3-5 orders where it did happen . Currently we can't log the issue,

[ghost]

Hi @gewaechshaus Can you provide steps to reproduce ? or can you reproduce on vanilla instance ?

[ghost]

@BezV8 , we are closing this issue due to inactivity. If you'd like to update it, please reopen the issue.

[bhagdave]

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)"} []

[karlsminton]

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)"} []

[ghost]

HI @karlsminton Can You describe how you get this error? to help us reproduce this issue?

[phongphanmage]

Same here. My Magento version 2.1.9.

[convenient]

I've seen this today. 2.1.7.

[karlsminton]

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.

[ghost]

Hi @BezV8 Hi @karlsminton I'm reopen this as many people have this issue.

[convenient]

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

• A paypal transaction.
• A quote in magento with the corresponding reserved_order_id
• No order entity within Magento for the payment to be matched against.

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

• Why was paypal able to auth and capture before returning a dodgy response? Additional logging in this handler to capture the full response from paypal may prove useful for debugging these errors.

Anyway it's been a long day debugging, but here's my notes anyway.

[kevinvarley]

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}

[kevinvarley]

@convenient Thank you for the detailed logging! Have you managed to get any further debugging the issue since your previous comment?

[perryholden]

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)"} []

[eInyzant]

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.

[kerlama]

Hi,

same on 2.1.15. Bunch of "Wrong order ID" errors in exception.log

[convenient]

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.

• We have seen a deadlock when creating the sales_invoice which caused the order to be rolled back which reverts the valid sales_order entry.
• The customer then ends up on paypal/express/review with the session message We can't place the order where they can attempt to press Place Order again.
• However this will fail as the paypal transaction has already been registered as complete by Paypal and the 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.)

--- 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.')

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

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.

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 quote updated_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

[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} [] []

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!

1. Ensure that payment/paypal_express/payment_action is set to Sale so that invoices are created when the payment is processed.

2. 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.

3. Clear your cookies / session / etc. Go through the checkout on the same store view and get as far as https://www.sandbox.paypal.com.

4. 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     |

5. 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);

6. 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.

7. 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.

• Hooks into sales_model_service_quote_submit_failure
• Only operates for orders where the exception message contains the string try restarting transaction
• Write log data to confirm a deadlocked order occurred.
• Use 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.

https://gist.github.com/convenient/ea1411d650e8765278338adc36deba93

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?

[magento-engcom-team]

@engcom-backlog-nazar Thank you for verifying the issue. Based on the provided information internal tickets MAGETWO-97869, MAGETWO-97870 were created

[ghost]

hi @convenient Thank you for your detailed explanation.

[bukos]

@engcom-backlog-nazar any update on this issue?, any workarounds available?

[tuxx42]

verified on 2.3.0. Please advise on how to solve this.

[Seiya7]

Same issue on 2.3.0.

[bikashkaushik]

[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)"} []

[gulshan-streammarket]

Have someone got any fix to this? I am also facing the same problem in Magento 2.2.7.

[toddca]

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.

[ghost]

Any update on the situation?

[kevinvarley]

Same issue 2.2.8

[horebecommerce]

Same issue 2.3.1, Any updates available so far?

[TonyRutherford1]

Same issue 2.3.1, customers complaining as orders are being missed. Any update on this bug?

[danci1973]

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)"} []

[boter3]

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)"} []

[TonyRutherford1]

@engcom-backlog-nazar Any updates? This is causing big issues for our client. Many orders being missed...

[kerlama]

Yes, all of our clients have the same issue. It would be highly appreciated to have some response.

[magento-engcom-team]

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.

[convenient]

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 ?

[TonyRutherford1]

@magento-engcom-team Has this been closed due to a fix in 2.3.2?

[csdougliss]

@magento-engcom-team Also seeing this in 2.3.1, can I get an update ASAP please?

[toddca]

@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.

[ci2014]

I can confirm this issue in 2.3

[brideo]

I'm seeing this in 2.3.1

[gewaechshaus]

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.

[csdougliss]

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?

[brideo]

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?

[kevinvarley]

2.2.9 affected

[csdougliss]

Still seeing this issue even after applying the patch I linked.

[horebecommerce]

@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

[djamps]

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?