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

Root exception not logged on QuoteManagement::submitQuote #21697

Conversation

david-fuehr
Copy link
Contributor

@david-fuehr david-fuehr commented Mar 11, 2019

Description

If an exceptions happens in \Magento\Sales\Api\OrderManagementInterface::place or an sales_model_service_quote_submit_success observer, the catch block itself fires an event. As you can not know, what these observers do, it should be wrapped in a try catch block itself.

With the Magento core this will currently happen, for example if saving the order throws an exception. This causes a rollback in \Magento\Framework\Model\ResourceModel\Db\AbstractDb::save. The catch in the order management triggers via an observer the method \Magento\CatalogInventory\Model\ResourceModel\Stock::correctItemsQty. In this method the stock modification is secured in a transaction - as the connection is already in rollback mode, the exception with the message Rolled back transaction has not been completed correctly. is thrown.

The problem is, that only the second exception is logged in exception.log - the preceding exception is very hard to find.

To handle this I wrapped the catch block itself in a try catch and merge the information in a new exception. This new exception is handled as before and finds its way to the exception.log.

Fixed Issues

  1. Rolled back transaction has not been completed correctly" on Magento 2.1.15 #18752: Rolled back transaction has not been completed correctly" on Magento 2.1.15
  2. "Rolled back transaction has not been completed correctly" on Magento 2.2.3 #14926: "Rolled back transaction has not been completed correctly" on Magento 2.2.3

Manual testing scenarios

I do not know another (simple) way of reproducing this bug, than introducing an exception in placement of order. In a real life scenario this exception may happen because of some runtime conditions (invalid credit card data - depending on PSP). It has to be either a rollback triggered in the try block of \Magento\Sales\Api\OrderManagementInterface::place or an exception in a sales_model_service_quote_submit_failure observers.

  1. Add this to the method \Magento\Sales\Model\ResourceModel\Order::_beforeSave:
    throw new \Exception('root of all evil');
  2. watch the exception log: tail -f <magento_root>/var/log/excption.log
  3. add products to cart
  4. proceed to checkout
  5. try to place the order
    1. the message 'An error occurred. Try to place the order again.' shows up in store front
    2. the log entry contains the message of the consecutive exception ('Rolled back transaction has not been completed correctly')
    3. the log entry contains the message of the preceding exception ('root of all evil').

Example

Log message without fix

report.CRITICAL: Rolled back transaction has not been completed correctly. {"exception":"[object]
(Exception(code: 0): Rolled back transaction has not been completed correctly. at
/Users/fuehrd/sources/magento2ce/lib/internal/Magento/Framework/DB/Adapter/Pdo/Mysql.php:277)"} []

Log message with fix

report.CRITICAL: An exception occurred on 'sales_model_service_quote_submit_failure' event: Rolled
back transaction has not been completed correctly. {"exception":"[object] (Exception(code: 0): An
exception occurred on 'sales_model_service_quote_submit_failure' event: Rolled back transaction has
not been completed correctly. at
/Users/fuehrd/sources/magento2ce/app/code/Magento/Quote/Model/QuoteManagement.php:555,
Exception(code: 0): root of all evil at
/Users/fuehrd/sources/magento2ce/app/code/Magento/Sales/Model/ResourceModel/Order.php:144)"}

Contribution checklist (*)

  • Pull request has a meaningful description of its purpose
  • All commits are accompanied by meaningful commit messages
  • All new or changed code is covered with unit/integration tests (if applicable)
  • All automated tests passed successfully (all builds on Travis CI are green)

Github Issue: magento#18752

If an exceptions happens in orderManagement->place($order) or an
"sales_model_service_quote_submit_success" observer, the catch block
itself fires an event that currently fails for guest checkouts in
Magento\CatalogInventory\Model\ResourceModel\Stock->correctItemsQty().

This second exception hides the root exception and is logged to
the exception log with the message "Rolled back transaction has not
been completed correctly".

This is not bound for this observer, but may occur in every other
observer that is currently register or may be registered in the future.

Therefore the failure event is wrapped in a try-catch itself and throws
a combined exception that is logged in the exception.log.
- support masking of root cause in frontend
- remove stack trace for consecutive exception to comply to default behaviour
@magento-engcom-team
Copy link
Contributor

Hi @david-fuehr. Thank you for your contribution
Here is some useful tips how you can test your changes using Magento test environment.
Add the comment under your pull request to deploy test or vanilla Magento instance:

  • @magento-engcom-team give me test instance - deploy test instance based on PR changes
  • @magento-engcom-team give me 2.3-develop instance - deploy vanilla Magento instance

For more details, please, review the Magento Contributor Assistant documentation

@rogyar
Copy link
Contributor

rogyar commented Mar 13, 2019

Hi @david-fuehr. Thank you for your idea. Please, check my comments in the review. Thanks

@david-fuehr
Copy link
Contributor Author

Hi @rogyar,

thanks for your review. I added some information to your review comment.

@rogyar
Copy link
Contributor

rogyar commented Mar 18, 2019

Great. Thank you

@magento-engcom-team
Copy link
Contributor

Hi @rogyar, thank you for the review.
ENGCOM-4520 has been created to process this Pull Request

@VasylShvorak
Copy link
Contributor

✔️ QA passed

@ghost
Copy link

ghost commented Mar 29, 2019

Hi @david-fuehr, thank you for your contribution!
Please, complete Contribution Survey, it will take less than a minute.
Your feedback will help us to improve contribution process.

@heqixi
Copy link

heqixi commented Jul 19, 2021

I reproduced this issue on magento2.4.2 - p1, steps are:

create a customer account in my landing page;
log in admin page, create a user (not a customer) account with the same email address which is used in step 1, and then save the user, the following excepion message was shown;

1 exception(s):
Exception #0 (Exception): Rolled back transaction has not been completed correctly.

Exception #0 (Exception): Rolled back transaction has not been completed correctly.

#1 Magento\Framework\DB\Adapter\Pdo\Mysql\Interceptor->___callParent() called at [vendor/magento/framework/Interception/Interceptor.php:138]
#2 Magento\Framework\DB\Adapter\Pdo\Mysql\Interceptor->Magento\Framework\Interception{closure}() called at [vendor/magento/framework/Interception/Interceptor.php:153]
#3 Magento\Framework\DB\Adapter\Pdo\Mysql\Interceptor->___callPlugins() called at [generated/code/Magento/Framework/DB/Adapter/Pdo/Mysql/Interceptor.php:32]
#4 Magento\Framework\DB\Adapter\Pdo\Mysql\Interceptor->commit() called at [vendor/magento/framework/Model/ResourceModel/AbstractResource.php:93]
#5 Magento\Framework\Model\ResourceModel\AbstractResource->commit() called at [vendor/magento/framework/Model/ResourceModel/Db/AbstractDb.php:426]
#6 Magento\Framework\Model\ResourceModel\Db\AbstractDb->save() called at [vendor/magento/framework/Model/AbstractModel.php:655]
#7 Magento\Framework\Model\AbstractModel->save() called at [vendor/magento/framework/Interception/Interceptor.php:58]
#8 Magento\User\Model\User\Interceptor->___callParent() called at [vendor/magento/framework/Interception/Interceptor.php:138]
#9 Magento\User\Model\User\Interceptor->Magento\Framework\Interception{closure}() called at [vendor/magento/framework/Interception/Interceptor.php:153]
#10 Magento\User\Model\User\Interceptor->___callPlugins() called at [generated/code/Magento/User/Model/User/Interceptor.php:581]
#11 Magento\User\Model\User\Interceptor->save() called at [vendor/magento/module-user/Controller/Adminhtml/User/Save.php:96]
#12 Magento\User\Controller\Adminhtml\User\Save->execute() called at [vendor/magento/framework/Interception/Interceptor.php:58]
#13 Magento\User\Controller\Adminhtml\User\Save\Interceptor->___callParent() called at [vendor/magento/framework/Interception/Interceptor.php:138]
#14 Magento\User\Controller\Adminhtml\User\Save\Interceptor->Magento\Framework\Interception{closure}() called at [vendor/magento/framework/App/Action/Plugin/ActionFlagNoDispatchPlugin.php:51]
#15 Magento\Framework\App\Action\Plugin\ActionFlagNoDispatchPlugin->aroundExecute() called at [vendor/magento/framework/Interception/Interceptor.php:135]
#16 Magento\User\Controller\Adminhtml\User\Save\Interceptor->Magento\Framework\Interception{closure}() called at [vendor/magento/framework/Interception/Interceptor.php:153]
#17 Magento\User\Controller\Adminhtml\User\Save\Interceptor->___callPlugins() called at [generated/code/Magento/User/Controller/Adminhtml/User/Save/Interceptor.php:23]
#18 Magento\User\Controller\Adminhtml\User\Save\Interceptor->execute() called at [vendor/magento/framework/App/Action/Action.php:111]
#19 Magento\Framework\App\Action\Action->dispatch() called at [vendor/magento/module-backend/App/AbstractAction.php:151]
#20 Magento\Backend\App\AbstractAction->dispatch() called at [vendor/magento/framework/Interception/Interceptor.php:58]
#21 Magento\User\Controller\Adminhtml\User\Save\Interceptor->___callParent() called at [vendor/magento/framework/Interception/Interceptor.php:138]
#22 Magento\User\Controller\Adminhtml\User\Save\Interceptor->Magento\Framework\Interception{closure}() called at [vendor/magento/module-backend/App/Action/Plugin/Authentication.php:143]
#23 Magento\Backend\App\Action\Plugin\Authentication->aroundDispatch() called at [vendor/magento/framework/Interception/Interceptor.php:135]
#24 Magento\User\Controller\Adminhtml\User\Save\Interceptor->Magento\Framework\Interception{closure}() called at [vendor/magento/framework/Interception/Interceptor.php:153]
#25 Magento\User\Controller\Adminhtml\User\Save\Interceptor->___callPlugins() called at [generated/code/Magento/User/Controller/Adminhtml/User/Save/Interceptor.php:32]
#26 Magento\User\Controller\Adminhtml\User\Save\Interceptor->dispatch() called at [vendor/magento/framework/App/FrontController.php:186]
#27 Magento\Framework\App\FrontController->processRequest() called at [vendor/magento/framework/App/FrontController.php:118]
#28 Magento\Framework\App\FrontController->dispatch() called at [vendor/magento/framework/Interception/Interceptor.php:58]
#29 Magento\Framework\App\FrontController\Interceptor->___callParent() called at [vendor/magento/framework/Interception/Interceptor.php:138]
#30 Magento\Framework\App\FrontController\Interceptor->Magento\Framework\Interception{closure}() called at [vendor/magento/framework/Interception/Interceptor.php:153]
#31 Magento\Framework\App\FrontController\Interceptor->___callPlugins() called at [generated/code/Magento/Framework/App/FrontController/Interceptor.php:23]
#32 Magento\Framework\App\FrontController\Interceptor->dispatch() called at [vendor/magento/framework/App/Http.php:116]
#33 Magento\Framework\App\Http->launch() called at [generated/code/Magento/Framework/App/Http/Interceptor.php:23]
#34 Magento\Framework\App\Http\Interceptor->launch() called at [vendor/magento/framework/App/Bootstrap.php:263]
#35 Magento\Framework\App\Bootstrap->run() called at [pub/index.php:29]

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

7 participants