Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
BezV8 opened this issue May 22, 2018 · 108 comments
Closed

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

BezV8 opened this issue May 22, 2018 · 108 comments
Assignees
Labels
Area: Payments Component: Sales Issue: Clear Description Gate 2 Passed. Manual verification of the issue description passed Issue: Format is valid Gate 1 Passed. Automatic verification of issue format passed Issue: needs update Additional information is require, waiting for response Issue: Ready for Work Gate 4. Acknowledged. Issue is added to backlog and ready for development Priority: P2 A defect with this priority could have functionality issues which are not to expectations. Progress: done Reproduced on 2.3.x The issue has been reproduced on latest 2.3 release Reproduced on 2.4.x The issue has been reproduced on latest 2.4-develop branch

Comments

@BezV8
Copy link
Contributor

BezV8 commented May 22, 2018

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).
@magento-engcom-team magento-engcom-team added the Issue: Format is valid Gate 1 Passed. Automatic verification of issue format passed label May 22, 2018
@ghost ghost self-assigned this Jul 26, 2018
@ghost ghost added Issue: Clear Description Gate 2 Passed. Manual verification of the issue description passed Progress: needs update labels Jul 26, 2018
@ghost
Copy link

ghost commented Jul 26, 2018

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

@gewaechshaus
Copy link

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

@BezV8
Copy link
Contributor Author

BezV8 commented Aug 2, 2018

@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
Copy link

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

@ghost ghost removed the Progress: needs update label Aug 17, 2018
@ghost
Copy link

ghost commented Aug 20, 2018

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

@ghost
Copy link

ghost commented Sep 3, 2018

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

@ghost ghost closed this as completed Sep 3, 2018
@bhagdave
Copy link

bhagdave commented Sep 5, 2018

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
Copy link

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
Copy link

ghost commented Sep 19, 2018

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

@phongphanmage
Copy link

Same here.
My Magento version 2.1.9.

@convenient
Copy link
Contributor

convenient commented Sep 28, 2018

I've seen this today. 2.1.7.

@karlsminton
Copy link

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
Copy link

ghost commented Sep 28, 2018

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

@ghost ghost reopened this Sep 28, 2018
@convenient
Copy link
Contributor

convenient commented Sep 28, 2018

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
Copy link

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
Copy link

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

@perryholden
Copy link

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
Copy link

eInyzant commented Nov 2, 2018

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
Copy link

kerlama commented Nov 21, 2018

Hi,

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

@convenient
Copy link
Contributor

convenient commented Jan 22, 2019

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

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

@ghost ghost added Component: Sales Reproduced on 2.2.x The issue has been reproduced on latest 2.2 release Reproduced on 2.3.x The issue has been reproduced on latest 2.3 release labels Jan 22, 2019
@Rohaty
Copy link

Rohaty commented Dec 20, 2022

Hi,

i have the same problem in magento 2.4.5-p1 in case the customer is logged in magento and make paypal payment. An error will appear

main.CRITICAL: Exception: The "40030822" order ID is incorrect. Verify the ID and try again. in /bitnami/magento/vendor/magento/module-paypal/Model/Ipn.php:147

At the same time, which is a problem, if I create an invoice for such an order, this invoice will be created twice, e.g. 10000201, 10000202.

If the customer is not logged in and makes the payment via paypal, there is no problem.

@JoostWan
Copy link

Same issue over here on version 2.4.6

@jdereus87
Copy link

Experiencing this issue with a 2.4.6-p3 installation.

#29 {main} {"exception":"[object] (Exception(code: 0): The "000207577" order ID is incorrect. Verify the ID and try again. at /data/web/magento2/vendor/magento/module-paypal/Model/Ipn.php:147)"} []
[2023-11-16T09:19:45.962002+00:00] main.CRITICAL: Exception: The "000207565" order ID is incorrect. Verify the ID and try again. in /data/web/magento2/vendor/magento/module-paypal/Model/Ipn.php:147
Stack trace:

@naseeraslam
Copy link

I am facing the same issue on Magento 2.4.4. The payment is successful on the PayPal side, but there is no corresponding order shown in the admin sales order grid.

@engcom-Hotel engcom-Hotel moved this to Ready for Development in High Priority Backlog Aug 19, 2024
@risecommerce
Copy link

Has anyone found a solution or workaround for this issue? Facing similar challenges and would appreciate any guidance. Thanks in advance!

@engcom-Delta
Copy link
Contributor

Hi @BezV8 ,

Thanks for your reporting and collaboration.
We have verified the issue in latest 2.4-develop instance, but we are unable to reproduce the issue. Kindly refer the screenshots.

Steps to reproduce
Scenario 1 -

  1. Customer Places Order
  2. Directed to PayPal page and payment taken
  3. Redirected to site.
  4. Observe the logs, "Wrong order ID" error is not generated.
    Scenario 2 -
  5. Customer Places Order
  6. Directed to PayPal page.
  7. Close the Paypal pop-up and navigate back to frontend. Observe message displays in shopping cart page.
    image
  8. Now, Navigate to checkout and place order using PayPal.
  9. Check logs, "Wrong order ID" error is not generated.

Please let us know if any other steps are needed to be performed.
Thanks.

@engcom-Delta engcom-Delta self-assigned this Oct 1, 2024
Copy link

m2-assistant bot commented Oct 1, 2024

Hi @engcom-Delta. Thank you for working on this issue.
Looks like this issue is already verified and confirmed. But if you want to validate it one more time, please, go though the following instruction:

    1. Add/Edit Area: XXXXX label to the ticket, indicating the functional areas it may be related to.
    1. Verify that the issue is reproducible on 2.4-develop branch
      Details- If the issue is reproducible on 2.4-develop branch, please, add the label Reproduced on 2.4.x.
      - If the issue is not reproducible, add your comment that issue is not reproducible and close the issue and stop verification process here!
    1. If the issue is not relevant or is not reproducible any more, feel free to close it.

@engcom-Delta engcom-Delta added Progress: ready for dev Issue: needs update Additional information is require, waiting for response and removed Issue: Confirmed Gate 3 Passed. Manual verification of the issue completed. Issue is confirmed Progress: dev in progress labels Oct 1, 2024
@engcom-Delta
Copy link
Contributor

Hi @BezV8 ,

We have noticed that this issue has not been updated since long time.
Hence we assume that this issue is fixed now, so we are closing it. Please feel to raise a fresh ticket or reopen this ticket if you need more assistance on this.

Thanks.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Area: Payments Component: Sales Issue: Clear Description Gate 2 Passed. Manual verification of the issue description passed Issue: Format is valid Gate 1 Passed. Automatic verification of issue format passed Issue: needs update Additional information is require, waiting for response Issue: Ready for Work Gate 4. Acknowledged. Issue is added to backlog and ready for development Priority: P2 A defect with this priority could have functionality issues which are not to expectations. Progress: done Reproduced on 2.3.x The issue has been reproduced on latest 2.3 release Reproduced on 2.4.x The issue has been reproduced on latest 2.4-develop branch
Projects
Status: Ready for Development
Development

No branches or pull requests