{"id":1598,"date":"2018-05-17T22:12:36","date_gmt":"2018-05-17T16:12:36","guid":{"rendered":"http:\/\/promincproductions.com\/blog\/?p=1598"},"modified":"2018-05-23T18:52:53","modified_gmt":"2018-05-23T12:52:53","slug":"magento-1-x-supee-10570-bug-session-timing-out","status":"publish","type":"post","link":"https:\/\/promincproductions.com\/blog\/magento-1-x-supee-10570-bug-session-timing-out\/","title":{"rendered":"Magento 1.x SUPEE-10570 Bug – Session Timing Out"},"content":{"rendered":"

After deploying a recent Magento security patch – SUPEE-10570<\/a> – I was receiving reports from fellow staff and customers that valid product pages were returning a 404 response.\u00a0 Oddly enough, if you logged into your customer account the page would be rendered just fine.<\/p>\n

\"\"<\/a>
Bugs have been identified in Magento 1.x SUPEE-10570 security patch – v1 and v2<\/figcaption><\/figure>\n

In a bit of a panic, I did pulled the major\u00a0reset<\/em> lever – a full reindex and cache flush of the full page cache and objects.\u00a0 And all was good!<\/p>\n

A random Magento oddity that will not reoccur – right?\u00a0 Wrong.\u00a0 It happened again.\u00a0 And again.\u00a0 And then vendors pointed it out to us as well…<\/p>\n

Additionally our internal staff seemed to be getting logged out of the Magneto admin at undesired times – like when submitting an order for a customer in the Magneto Admin…<\/p>\n

Magento Installation<\/h2>\n

This issue was happening on a Magento Enterprise 1.14.2.0 fully patched site, including SUPEE-10570 v2 (though v1 is affected by this as well).<\/p>\n

I have not looked into the Magneto 2 code to see if the same issue exists there.<\/p>\n

SUPEE-10570 Bugs<\/h2>\n

The root bug with this patch is that it is setting a timestamp in the visitors session which is used to validate if a malicious person is trying to hijack session cookie.\u00a0 The timestamp will expire based on the session lifetime settings set in the Magento for the frontend and admin.<\/p>\n

If that timestamp is in the past, Magento will invalidate the session.\u00a0 But it is not handled gracefully…\u00a0 And worse yet, not all timestamps are updated as expected.<\/p>\n

In the users session stored on the server there are several namespaces – each of which have the session validation timestamp stored to them.\u00a0 But not all pages use all of the namespaces.\u00a0 So it’s possible to get a stale timestamp stored in your session.<\/p>\n

Worse yet, if you are using the Full Page Cache (from Enterprise), the block of code that should update one of the namespaces – reports (for tracking page view stats) – isn’t called if the page is stored in the fullpage cache.\u00a0 For this reason it’s very easy for a visitor to have a stale timestamp in their session, which will result in an exception thrown in your server logs (exception.log) and a 404 page being returned to the visitor.\u00a0 Worse yet, that 404 response is now stored in the full page cache for future visitors to find!<\/p>\n

This same scenario plays into the Magento admin as well.\u00a0 I haven’t dug as deep into how that is all affected but am aware that it is and that the below fix resolves the issues.<\/p>\n

Exception Thrown in exception.log<\/h2>\n

When Magento detects a stale timestamp from the\u00a0Reports<\/strong> module, it throws the following exception:<\/p>\n

2018-05-09T10:04:18+00:00 ERR (3):\r\nexception 'Mage_Core_Model_Session_Exception' in \/var\/www\/vhosts\/mysite.com\/html\/app\/code\/core\/Mage\/Core\/Model\/Session\/Abstract\/Varien.php:421\r\nStack trace:\r\n#0 \/var\/www\/vhosts\/mysite.com\/html\/app\/code\/core\/Mage\/Core\/Model\/Session\/Abstract\/Varien.php(236): Mage_Core_Model_Session_Abstract_Varien->validate()\r\n#1 \/var\/www\/vhosts\/mysite.com\/html\/app\/code\/core\/Mage\/Core\/Model\/Session\/Abstract.php(84): Mage_Core_Model_Session_Abstract_Varien->init('reports', NULL)\r\n#2 \/var\/www\/vhosts\/mysite.com\/html\/app\/code\/core\/Mage\/Reports\/Model\/Session.php(43): Mage_Core_Model_Session_Abstract->init('reports')\r\n#3 \/var\/www\/vhosts\/mysite.com\/html\/app\/code\/core\/Mage\/Core\/Model\/Config.php(1354): Mage_Reports_Model_Session->__construct(Array)\r\n#4 \/var\/www\/vhosts\/mysite.com\/html\/app\/Mage.php(463): Mage_Core_Model_Config->getModelInstance('reports\/session', Array)\r\n#5 \/var\/www\/vhosts\/mysite.com\/html\/app\/Mage.php(477): Mage::getModel('reports\/session', Array)\r\n#6 \/var\/www\/vhosts\/mysite.com\/html\/app\/code\/core\/Mage\/Reports\/Model\/Product\/Index\/Abstract.php(158): Mage::getSingleton('reports\/session')\r\n#7 \/var\/www\/vhosts\/mysite.com\/html\/app\/code\/core\/Mage\/Reports\/Model\/Product\/Index\/Abstract.php(176): Mage_Reports_Model_Product_Index_Abstract->_getSession()\r\n#8 \/var\/www\/vhosts\/mysite.com\/html\/app\/code\/core\/Mage\/Reports\/Model\/Event\/Observer.php(148): Mage_Reports_Model_Product_Index_Abstract->calculate()\r\n#9 \/var\/www\/vhosts\/mysite.com\/html\/app\/code\/core\/Mage\/Core\/Model\/App.php(1339): Mage_Reports_Model_Event_Observer->catalogProductView(Object(Varien_Event_Observer))\r\n#10 \/var\/www\/vhosts\/mysite.com\/html\/app\/code\/core\/Mage\/Core\/Model\/App.php(1318): Mage_Core_Model_App->_callObserverMethod(Object(Mage_Reports_Model_Event_Observer), 'catalogProductV...', Object(Varien_Event_Observer))\r\n#11 \/var\/www\/vhosts\/mysite.com\/html\/app\/Mage.php(448): Mage_Core_Model_App->dispatchEvent('catalog_control...', Array)\r\n#12 \/var\/www\/vhosts\/mysite.com\/html\/app\/code\/core\/Mage\/Catalog\/Helper\/Product\/View.php(135): Mage::dispatchEvent('catalog_control...', Array)\r\n#13 \/var\/www\/vhosts\/mysite.com\/html\/app\/code\/core\/Mage\/Catalog\/controllers\/ProductController.php(132): Mage_Catalog_Helper_Product_View->prepareAndRender(827, Object(OnePica_Catalog_ProductController), Object(Varien_Object))\r\n#14 \/var\/www\/vhosts\/mysite.com\/html\/app\/code\/core\/Mage\/Core\/Controller\/Varien\/Action.php(398): Mage_Catalog_ProductController->viewAction()\r\n#15 \/var\/www\/vhosts\/mysite.com\/html\/app\/code\/core\/Mage\/Core\/Controller\/Varien\/Router\/Standard.php(254): Mage_Core_Controller_Varien_Action->dispatch('view')\r\n#16 \/var\/www\/vhosts\/mysite.com\/html\/app\/code\/core\/Mage\/Core\/Controller\/Varien\/Front.php(172): Mage_Core_Controller_Varien_Router_Standard->match(Object(Mage_Core_Controller_Request_Http))\r\n#17 \/var\/www\/vhosts\/mysite.com\/html\/app\/code\/core\/Mage\/Core\/Model\/App.php(354): Mage_Core_Controller_Varien_Front->dispatch()\r\n#18 \/var\/www\/vhosts\/mysite.com\/html\/app\/Mage.php(684): Mage_Core_Model_App->run(Array)\r\n#19 \/var\/www\/vhosts\/mysite.com\/html\/index.php(83): Mage::run('default', 'store')\r\n#20 {main}<\/pre>\n
Long Standing Additional Bug Identified By This Issue<\/h2>\n
It seems to me that the report function of Magento that reports product view counts is not working as desired when the Full Page Cache is enabled.\u00a0 As mentioned above, that block of code is not called when a page is stored in the Full Page Cache, thus the counter is never updated…<\/p>\n
Steps to Recreate the 404 Product Page Bug<\/h2>\n
    \n
  1. Enable the Full Page Cache in the Magento Admin<\/li>\n
  2. Set the session Cookie Lifetime to a low value for testing like 60 (1 minute)<\/li>\n
  3. Clear the full page cache<\/li>\n
  4. Visit a product page (it should render as expected)<\/li>\n
  5. Visit a category page<\/li>\n
  6. Wait until the session Cookie Lifetime has lapsed – wait 60+ seconds based on the above suggested settings<\/li>\n
  7. Visit any product page (except that visited in step 4) – a 404 response is shown to the customer.\n
      \n
    1. This 404 response is stored in the full page cache – as will be verified by step 8 below.<\/li>\n
    2. View the exception.log file to notice an exception thrown – exception ‘Mage_Core_Model_Session_Exception’ in \/var\/www\/vhosts\/mysite.com\/html\/app\/code\/core\/Mage\/Core\/Model\/Session\/Abstract\/Varien.php<\/li>\n<\/ol>\n<\/li>\n
    3. Open a different browser\/session and visit the same product page as step 7\n
        \n
      1. a 404 response is shown to this now new visitor<\/em>\u00a0because the page is stored in the full page cache.\u00a0<\/li>\n<\/ol>\n<\/li>\n<\/ol>\n
        Magento Support<\/h2>\n
        I have brought this issue to the attention of Magento Support.\u00a0 It’s my understanding that they are working on a resolution and I will certainly update this post when I know more.\u00a0 But honestly their responses are rather vague and I have already implemented a working solution, so I have put that ticket on the sideburner a bit.\u00a0 They never did acknowledge if they can recreate the issue or not oddly enough…\u00a0 but have said they are working on my ticket…<\/p>\n
        Source of the Bug<\/h2>\n
        The source of the bug is this bit of code added by patch SUPEE-10570:<\/p>\n
        ## File: app\/code\/core\/Mage\/Core\/Model\/Session\/Abstract\/Varien.php\r\n## Lines: 465-472\r\n\r\n        if ($this->useValidateSessionExpire()\r\n            && isset($sessionData[self::VALIDATOR_SESSION_EXPIRE_TIMESTAMP])\r\n            && $sessionData[self::VALIDATOR_SESSION_EXPIRE_TIMESTAMP] < time() ) {\r\n            return false;\r\n        } else {\r\n            $this->_data[self::VALIDATOR_KEY][self::VALIDATOR_SESSION_EXPIRE_TIMESTAMP]\r\n                = $validatorData[self::VALIDATOR_SESSION_EXPIRE_TIMESTAMP];\r\n        }\r\n<\/pre>\n
        This is where Magento checks the timestamp.\u00a0 When Magento returns false there can be undesired, depending on what namespace called the\u00a0validate()<\/strong> function.<\/p>\n
        Mitigating the Session Timeout Bug<\/h2>\n
        Mitigation is simple – just comment out \/ remove the problematic lines of code.<\/p>\n
        I personally don’t suggest modifying core files – as does any good Magneto developer.\u00a0 For that reason, you should copy the entire file to the local path:<\/p>\n
        app\/code\/local\/Mage\/Core\/Model\/Session\/Abstract\/Varien.php<\/pre>\n
        NOTE: Because this a an abstract file you do need to copy the entire file – not just the method you are overriding.<\/p>\n
        In that local file you can then comment out these lines and all will be resolved.\u00a0 That said, this is a mitigation – NOT a Magento approved\/supplied fix.<\/p>\n
        Magento intended to add this step of validation for security reasons.\u00a0 I don’t personally feel this really helps much of anything in terms of security, but I’ve never claimed to be a security expert either – I’m a developer.\u00a0 Also, if\/when Magento does publish a solution to this issue we will likely need to remove this mitigation, so keep in mind that implementing this may require additional maintenance in the future.<\/p>","protected":false},"excerpt":{"rendered":"
        After deploying a recent Magento security patch – SUPEE-10570 – I was receiving reports from fellow staff and […]<\/p>\n","protected":false},"author":1,"featured_media":1599,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"wprm-recipe-roundup-name":"","wprm-recipe-roundup-description":"","_jetpack_newsletter_access":"","_jetpack_dont_email_post_to_subs":false,"_jetpack_newsletter_tier_id":0,"_jetpack_memberships_contains_paywalled_content":false,"_jetpack_memberships_contains_paid_content":false,"footnotes":"","jetpack_post_was_ever_published":false},"categories":[46,5],"tags":[],"class_list":["post-1598","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-magento","category-website-development"],"jetpack_featured_media_url":"https:\/\/promincproductions.com\/blog\/wp-content\/uploads\/2018\/05\/Magento-SUPEE-10570-Bug.jpg","jetpack_shortlink":"https:\/\/wp.me\/p4BbcR-pM","jetpack_sharing_enabled":true,"amp_enabled":true,"_links":{"self":[{"href":"https:\/\/promincproductions.com\/blog\/wp-json\/wp\/v2\/posts\/1598","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/promincproductions.com\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/promincproductions.com\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/promincproductions.com\/blog\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/promincproductions.com\/blog\/wp-json\/wp\/v2\/comments?post=1598"}],"version-history":[{"count":2,"href":"https:\/\/promincproductions.com\/blog\/wp-json\/wp\/v2\/posts\/1598\/revisions"}],"predecessor-version":[{"id":1602,"href":"https:\/\/promincproductions.com\/blog\/wp-json\/wp\/v2\/posts\/1598\/revisions\/1602"}],"wp:featuredmedia":[{"embeddable":true,"href":"https:\/\/promincproductions.com\/blog\/wp-json\/wp\/v2\/media\/1599"}],"wp:attachment":[{"href":"https:\/\/promincproductions.com\/blog\/wp-json\/wp\/v2\/media?parent=1598"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/promincproductions.com\/blog\/wp-json\/wp\/v2\/categories?post=1598"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/promincproductions.com\/blog\/wp-json\/wp\/v2\/tags?post=1598"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}