Throw exception to prevent infinite loop caused by third party code. #1244

empiricompany · 2020-10-01T12:36:44Z

Integrate solution from @convenient for issues described in the pull request on magento2 repository
magento/magento2#18678

In our case the problem occurred with the MSP_CashOnDelivery extension, after a long debugging session we were able to identify and reproduce the problem and trace the MSP_CashOnDelivery extension causes an infinite loop and timeout of the request if trigger_recollect column is set to 1 in the sales_flat_quote table

It would be useful to integrate this solution from @convenient that throw new Exception to quickly identify any third party extensions affected by the same problem

But can there be copyright problems in this case? and in the future how can we do for porting a bug fixed on magento 2 to magento-lts?

Description (*)

Related Pull Requests

Fixed Issues (if relevant)

Fixes OpenMage/magento-lts#<issue_number>

Manual testing scenarios (*)

...
...

Questions or comments

Contribution checklist (*)

Pull request has a meaningful description of its purpose
All commits are accompanied by meaningful commit messages
All automated tests passed successfully (all builds are green)

@convenient

Integrate solution from @convenient for issues described in the pull request on magento2 repository magento/magento2#18678 In our case the problem occurred with the MSP_CashOnDelivery extension, after a long debugging session we were able to identify and reproduce the problem and trace the MSP_CashOnDelivery extension causes an infinite loop and timeout of the request if trigger_recollect column is set to 1 in the sales_flat_quote table It would be useful to integrate this solution from @convenient that throw new Exception to quickly identify any third party extensions affected by the same problem But can there be copyright problems in this case? and in the future how can we do for porting a bug fixed on magento 2 to magento-lts?

convenient · 2020-10-01T14:00:57Z

Licensing aside this patch pretty much matches my initial version. I applied this to a M1 client a few years back when debugging infinite looping quotes on a production site, that formed the basis of my M2 pull request.

empiricompany · 2020-10-06T08:06:48Z

after further hours of debugging and testing I think the definitive solution to the problem is this:
magento/magento2@bddb976
although I would leave the change in Mage_Checkout_Model_Session to raise an exception if a loop occurs

Related Pull Requests

#1248

Fix

/**
 * Trigger collect totals after loading, if required
 *
 * @return Mage_Sales_Model_Quote
 */
protected function _afterLoad()
{
    // collect totals and save me, if required
    if (1 == $this->getData('trigger_recollect')) {
        $this->setData('trigger_recollect', 0)->save();       // reset trigger_recollect before collectsTotals
        $this->collectTotals()->save();
    }
    return parent::_afterLoad();
}

Description

if a customer quote is marked with the "trigger_recollect" flag
and a payment or shipping method loads the quote model in its "collect" method
Mage_Sales_Model_Quote:_afterLoad() method is recalled which attempts to recollect totals causing the loop

More detail description

if "trigger_recollect" is marked, after loading the quote Mage_Sales_Model_Quote the Mage_Sales_Model_Quote::collectTotals() method is called from Mage_Sales_Model_Quote::_afterLoad() which calls the "collect" method for each model of 3rd party payment / shipping method.

class Mage_Sales_Model_Quote extends Mage_Core_Model_Abstract
.. ..
    public function collectTotals()
    {
.. ..
        foreach ($this->getAllAddresses() as $address) {
.. ..
            $address->collectTotals();

class Mage_Sales_Model_Quote_Address extends Mage_Customer_Model_Address_Abstract
..
    public function collectTotals()
    {
        Mage::dispatchEvent($this->_eventPrefix . '_collect_totals_before', array($this->_eventObject => $this));
        foreach ($this->getTotalCollector()->getCollectors() as $model) {
            $model->collect($this);
        }
        Mage::dispatchEvent($this->_eventPrefix . '_collect_totals_after', array($this->_eventObject => $this));
        return $this;
    }

if one of these $models attempts to reloading the quote Mage_Sales_Model_Quote::_afterload() method is recalled and Mage_Sales_Model_Quote::recollectTotals() restarts causing the loop

Reproduction of the scenario call stack:

Mage_Sales_Model_Quote::load()
Mage_Sales_Model_Quote::_afterLoad()
Mage_Sales_Model_Quote::collectTotals();
=> on line 1331 foreach address entity Mage_Sales_Model_Quote_Address->collectTotals();
Mage_Sales_Model_Quote_Address::collectTotals()

    /**
     * Collect address totals
     *
     * @return Mage_Sales_Model_Quote_Address
     */
    public function collectTotals()
    {
        Mage::dispatchEvent($this->_eventPrefix . '_collect_totals_before', array($this->_eventObject => $this));
        foreach ($this->getTotalCollector()->getCollectors() as $model) {
            $model->collect($this);
        }
        Mage::dispatchEvent($this->_eventPrefix . '_collect_totals_after', array($this->_eventObject => $this));
        return $this;
    }

here if some 3rd party payment/shipping method in its collect() method reload the quote before collectTotals ended and "trigger_recollect" is marked starts the loop

in our case MSP_CashOnDelivery_Helper_Data::getQuote() call Mage_Checkout_Model_Session->getQuote() that attempts to loading the quote into the session

#0 /var/www/app/code/community/MSP/CashOnDelivery/Helper/Data.php(118): Mage_Checkout_Model_Session->getQuote()
#1 /var/www/app/code/community/MSP/CashOnDelivery/Model/Cashondelivery.php(50): MSP_CashOnDelivery_Helper_Data->getQuote()
#2 /var/www/app/code/community/MSP/CashOnDelivery/Model/Quote/Total.php(36):

reloading the quote before collectTotals()

class Mage_Checkout_Model_Session extends Mage_Core_Model_Session_Abstract
...
    public function getQuote()
    {
        Mage::dispatchEvent('custom_quote_process', array('checkout_session' => $this));

        if ($this->_quote === null) {
            if ($this->_isLoading) {
                throw new Exception("Infinite loop detected, review the trace for the looping path");
            }
            $this->_isLoading = true;
            /** @var $quote Mage_Sales_Model_Quote */
            $quote = Mage::getModel('sales/quote')->setStoreId(Mage::app()->getStore()->getId());
            if ($this->getQuoteId()) {
                if ($this->_loadInactive) {
                    $quote->load($this->getQuoteId());
                } else {
                    $quote->loadActive($this->getQuoteId());
                }

Our complete backtrace of the loop:

Error:
Infinite loop detected, review the trace for the looping path

Trace:
#0 /var/www/app/code/community/MSP/CashOnDelivery/Helper/Data.php(118): Mage_Checkout_Model_Session->getQuote()
#1 /var/www/app/code/community/MSP/CashOnDelivery/Model/Cashondelivery.php(50): MSP_CashOnDelivery_Helper_Data->getQuote()
#2 /var/www/app/code/community/MSP/CashOnDelivery/Model/Quote/Total.php(36): MSP_CashOnDelivery_Model_Cashondelivery->getBaseExtraFee()
#3 /var/www/app/code/core/Mage/Sales/Model/Quote/Address.php(1013): MSP_CashOnDelivery_Model_Quote_Total->collect(Object(TM_FireCheckout_Model_Quote_Address))
#4 /var/www/app/code/core/Mage/Sales/Model/Quote.php(1331): Mage_Sales_Model_Quote_Address->collectTotals()
#5 /var/www/app/code/core/Mage/Sales/Model/Quote.php(1908): Mage_Sales_Model_Quote->collectTotals()
#6 /var/www/app/code/core/Mage/Sales/Model/Quote.php(376): Mage_Sales_Model_Quote->**_afterLoad**()
#7 /var/www/app/code/core/Mage/Checkout/Model/Session.php(140): Mage_Sales_Model_Quote->loadActive('97130')
// start of the loop
#8 /var/www/app/code/community/MSP/CashOnDelivery/Helper/Data.php(118): Mage_Checkout_Model_Session->getQuote()
#9 /var/www/app/code/community/MSP/CashOnDelivery/Model/Cashondelivery.php(50): MSP_CashOnDelivery_Helper_Data->getQuote()
#10 /var/www/app/code/community/MSP/CashOnDelivery/Model/Quote/Total.php(36): MSP_CashOnDelivery_Model_Cashondelivery->getBaseExtraFee()
#11 /var/www/app/code/core/Mage/Sales/Model/Quote/Address.php(1013): MSP_CashOnDelivery_Model_Quote_Total->collect(Object(TM_FireCheckout_Model_Quote_Address))
#12 /var/www/app/code/core/Mage/Sales/Model/Quote.php(1331): Mage_Sales_Model_Quote_Address->collectTotals()
#13 /var/www/app/code/core/Mage/Sales/Model/Quote.php(1908): Mage_Sales_Model_Quote->collectTotals()
#14 /var/www/app/code/core/Mage/Sales/Model/Quote.php(376): Mage_Sales_Model_Quote->**_afterLoad**()
#15 /var/www/app/code/core/Mage/Checkout/Model/Session.php(140): Mage_Sales_Model_Quote->loadActive('97130')
// start of the loop
#16 /var/www/app/code/community/MSP/CashOnDelivery/Helper/Data.php(118): Mage_Checkout_Model_Session->getQuote()
#17 /var/www/app/code/community/MSP/CashOnDelivery/Model/Cashondelivery.php(50): MSP_CashOnDelivery_Helper_Data->getQuote()
#18 /var/www/app/code/community/MSP/CashOnDelivery/Model/Quote/Total.php(36): MSP_CashOnDelivery_Model_Cashondelivery->getBaseExtraFee()
#19 /var/www/app/code/core/Mage/Sales/Model/Quote/Address.php(1013): MSP_CashOnDelivery_Model_Quote_Total->collect(Object(TM_FireCheckout_Model_Quote_Address))
#20 /var/www/app/code/core/Mage/Sales/Model/Quote.php(1331): Mage_Sales_Model_Quote_Address->collectTotals()
#21 /var/www/app/code/core/Mage/Sales/Model/Quote.php(1908): Mage_Sales_Model_Quote->collectTotals()
#22 /var/www/app/code/core/Mage/Sales/Model/Quote.php(376): Mage_Sales_Model_Quote->**_afterLoad**()
#23 /var/www/app/code/core/Mage/Checkout/Model/Session.php(140): Mage_Sales_Model_Quote->loadActive('97130')

...
...

empiricompany · 2020-10-23T07:00:59Z

I must advise against this pull request as it causes problems with many widely used modules such as MSP_CashOnDelivery and others.

We have definitely solved the issues thanks to this change #1248
on a production site with different catalog rules that makes about 200 orders a day

convenient · 2020-10-23T07:02:29Z

@empiricompany surely it only causes an exception when an infinite loop is about to occur?

empiricompany · 2020-10-23T07:11:12Z

@convenient yes but many widely used extensions have this problem that occurs when there are products in the cart affected by unsynchronized catalog rules, because the extension prevents the setting of the trigger_recollect flag causing the loop.
The modification can be fine for debugging purposes but in production it would produce a lot of backward compatibility problems with many shops that use these extensions that would have to be totally rewritten to solve.

convenient · 2020-10-23T07:15:25Z

@empiricompany I agree there will be a lot of modules out there with this problem that could be affected by this PR.

But in the request flow where this logic exception fires isn't that particular request already broken because it will be in an infinite loop.

This PR was never meant to fix anything, just to prevent requests gobbling up all the system resources and to give a useful stack trace.

The infinite loop requests may be currently being killed by Max execution time limits for example, but they are still broken requests. This PR just breaks them earlier with a clear stack trace.

I can't see how this PR would make anything worse, the purpose of throwing a logic exception is to tell you you have a but somewhere else in your code.

empiricompany · 2020-10-23T07:43:16Z

@convenient in our experience with some catalog rules that affects the cart and the MSP_CashOnDelivery extension this exception was useful for us to identify the problem but we had to remove it otherwise it was raised because it seems to me that it must do at least "2 loop cycles" (or more depends on how many extension causing the loop) before stopping thanks to the setting of the flag "trigger_recollect".
In fact, an alternative we have adopted would be to set a counter instead of the simple flag boolean _isLoading and stopping only if _isLoading < 5 in order to stop the loop and be able to see the complete stack.
I have no proof that this mod with the "trigger_recollect" flag fix (#1248) does not cause any problems.
Instead we are sure that the problem is solved with this #1248.
I'm afraid that many shops will have problems merging this change.

convenient · 2020-10-23T08:11:26Z

@empiricompany Ahhh interesting I have never actually come across a scenario where multiple loops are needed, it's always been one loop in my experiences.

Having a counter could also work I suppose then and there is precedent within the magento core like in the router

magento-lts/app/code/core/Mage/Core/Controller/Varien/Front.php

Lines 188 to 200 in 8ca6fd9

    
           $i = 0; 
        
           while (!$request->isDispatched() && $i++ < 100) { 
        
               foreach ($this->_routers as $router) { 
        
                   /** @var Mage_Core_Controller_Varien_Router_Abstract $router */ 
        
                   if ($router->match($request)) { 
        
                       break; 
        
                   } 
        
               } 
        
           } 
        
           Varien_Profiler::stop('mage::dispatch::routers_match'); 
        
           if ($i>100) { 
        
               Mage::throwException('Front controller reached 100 router match iterations'); 
        
           }

empiricompany · 2020-10-23T08:20:28Z

@convenient I can confirm that even after the modification suggested by @colinmollenhour in the PR #1248 and with the simple flag isLoading any problematic extensions such as MSP_CashOnDelivery cannot get out of the loop. We have tested it in production.
Currently we have a very tolerant counter <50 to avoid any infinite loops in extremis and have the full stack dump before closing the request in a timeout.


/**
     * A flag to track when the quote is being loaded and attached to the session object.
     *
     * Used in trigger_recollect infinite loop detection.
     *
     * @var bool
     */
    protected $_isLoading = 0;

/**
     * Get checkout quote instance by current session
     *
     * @return Mage_Sales_Model_Quote
     */
    public function getQuote()
    {
        Mage::dispatchEvent('custom_quote_process', array('checkout_session' => $this));

        if ($this->_quote === null) {
            if ($this->_isLoading > 50) {
                throw new Exception("Infinite loop detected, review the trace for the looping path");
            }
            $this->_isLoading++;
            /** @var $quote Mage_Sales_Model_Quote */
            $quote = Mage::getModel('sales/quote')->setStoreId(Mage::app()->getStore()->getId());
            if ($this->getQuoteId()) {
                if ($this->_loadInactive) {
                    $quote->load($this->getQuoteId());
                } else {
                    $quote->loadActive($this->getQuoteId());
                }
                if ($quote->getId()) {
                    /**
                     * If current currency code of quote is not equal current currency code of store,
                     * need recalculate totals of quote. It is possible if customer use currency switcher or
                     * store switcher.
                     */
                    if ($quote->getQuoteCurrencyCode() != Mage::app()->getStore()->getCurrentCurrencyCode()) {
                        $quote->setStore(Mage::app()->getStore());
                        $quote->collectTotals()->save();
                        /*
                         * We mast to create new quote object, because collectTotals()
                         * can to create links with other objects.
                         */
                        $quote = Mage::getModel('sales/quote')->setStoreId(Mage::app()->getStore()->getId());
                        $quote->load($this->getQuoteId());
                    }
                } else {
                    $this->setQuoteId(null);
                }
            }

            $customerSession = Mage::getSingleton('customer/session');

            if (!$this->getQuoteId()) {
                if ($customerSession->isLoggedIn() || $this->_customer) {
                    $customer = ($this->_customer) ? $this->_customer : $customerSession->getCustomer();
                    $quote->loadByCustomer($customer);
                    $this->setQuoteId($quote->getId());
                } else {
                    $quote->setIsCheckoutCart(true);
                    Mage::dispatchEvent('checkout_quote_init', array('quote'=>$quote));
                }
            }

            if ($this->getQuoteId()) {
                if ($customerSession->isLoggedIn() || $this->_customer) {
                    $customer = ($this->_customer) ? $this->_customer : $customerSession->getCustomer();
                    $quote->setCustomer($customer);
                }
            }

            $quote->setStore(Mage::app()->getStore());
            $this->_quote = $quote;
            $this->_isLoading = 0;
        }

convenient · 2020-10-23T09:18:01Z

@empiricompany that seems like a great amendment

Flyingmana · 2021-01-20T10:27:19Z

Thank you for your contributions and the very interesting discussion here.

As we have merged #1248, it seems we do not need to merge this one for now. Especially as @empiricompany is currently advising against merging it.

Still, if someone else may run into similar problems, we may reopen it and potentially merge it into a later version which is allowed to be less backwards compatible.
Of course with the suggested changes regarding a counter.(I also remember cases where the totals did need more then one run)

convenient · 2021-01-20T10:34:26Z

@Flyingmana all makes sense. But to be clear this isn't about collecting the totals more than once, but collecting the totals more than once without the quote having being assigned to the session singleton.

A very subtle difference.

github-actions bot added the Component: Checkout Relates to Mage_Checkout label Oct 1, 2020

empiricompany mentioned this pull request Oct 6, 2020

mark trigger_recollect before collectTotals #1248

Merged

3 tasks

kkrieger85 approved these changes Oct 22, 2020

View reviewed changes

empiricompany closed this Jan 20, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Uh oh!

Throw exception to prevent infinite loop caused by third party code. #1244

Throw exception to prevent infinite loop caused by third party code. #1244

Uh oh!

empiricompany commented Oct 1, 2020

Uh oh!

convenient commented Oct 1, 2020

Uh oh!

empiricompany commented Oct 6, 2020

Uh oh!

empiricompany commented Oct 23, 2020

Uh oh!

convenient commented Oct 23, 2020

Uh oh!

empiricompany commented Oct 23, 2020

Uh oh!

convenient commented Oct 23, 2020

Uh oh!

empiricompany commented Oct 23, 2020

Uh oh!

convenient commented Oct 23, 2020

Uh oh!

empiricompany commented Oct 23, 2020

Uh oh!

convenient commented Oct 23, 2020

Uh oh!

Flyingmana commented Jan 20, 2021

Uh oh!

convenient commented Jan 20, 2021

Uh oh!

Uh oh!

Uh oh!

Throw exception to prevent infinite loop caused by third party code. #1244

Throw exception to prevent infinite loop caused by third party code. #1244

Uh oh!

Conversation

empiricompany commented Oct 1, 2020

Description (*)

Related Pull Requests

Fixed Issues (if relevant)

Manual testing scenarios (*)

Questions or comments

Contribution checklist (*)

Uh oh!

convenient commented Oct 1, 2020

Uh oh!

empiricompany commented Oct 6, 2020

Related Pull Requests

Fix

Description

More detail description

Reproduction of the scenario call stack:

Uh oh!

empiricompany commented Oct 23, 2020

Uh oh!

convenient commented Oct 23, 2020

Uh oh!

empiricompany commented Oct 23, 2020

Uh oh!

convenient commented Oct 23, 2020

Uh oh!

empiricompany commented Oct 23, 2020

Uh oh!

convenient commented Oct 23, 2020

Uh oh!

empiricompany commented Oct 23, 2020

Uh oh!

convenient commented Oct 23, 2020

Uh oh!

Flyingmana commented Jan 20, 2021

Uh oh!

convenient commented Jan 20, 2021

Uh oh!

Uh oh!