Session validation failure in Magento 1 EE v 1.14.3.x (and CE 1.9.3.x)

Question

I'm looking after a Magento shop with 400-500 visitors and 40-50 orders per day. Recently system was upgraded from Magento EE 1.14.2.4 to Magento EE 1.14.3.2 and I noticed some strange exceptions in logs:

exception 'Mage_Core_Model_Session_Exception' in
/var/www/.../app/code/core/Mage/Core/Model/Session/Abstract/Varien.php:418

I was chasing that exception and I do know that it is being fired because the following session validation code fails to validate the session:

class Mage_Core_Model_Session_Abstract_Varien extends Varien_Object
{
// ...
    protected function _validate()
    {
//    ...
        if ($this->useValidateSessionExpire()
            && isset($sessionData[self::VALIDATOR_SESSION_EXPIRE_TIMESTAMP])
            && $sessionData[self::VALIDATOR_SESSION_EXPIRE_TIMESTAMP] < time() ) {

This if-block was added to the file with latest release from Magento. And this is a braking change apparently, see more details below.

The exception is happening quite often, like a dozen times per day. but I'm not able to recreate conditions which lead to the exception, unless I literally put true in the condition above. The exceptions most often occurs on product detail pages and on the last step of one page checkout. The shop is a b2b shop, the user must be logged in to see product page or to be able to checkout, means user is redirected to login pages when session is invalidated/expired. At the moment it is more important for me to fix this problem during checkout.

What happens from user perspective: User fills the cart, proceeds to checkout and reaches last step, then he/she hits the "submit the order" button and nothing happens. Behind the scenes Magento's JS performs an AJAX request and JS expects to receive JSON back, but if this error happens the HTML of login page is returned, which can not be parsed by JavaScript and it just does nothing. That is super confusing for users.

Well, that is not complete user scenario, we contacted users and they told us that they waited for few days between filling the cart and submitting the order, what that exactly means is hard to figure out, because people simply don't remember that.

PHP session lifetime - 350000 (~4 days in seconds) Cookie lifetime - 345600 (4 days)

Here is the actual question: how can I find out what sort of user behavior lead to the exception?

UPDATE So far I know that exception happens in following classes according to the request made, to me that means nothing unfortunately.

/catalogsearch/result/?q=…    Mage_Core_Model_Session
/checkout/cart/               Mage_Core_Model_Session
/checkout/onepage/saveOrder/… Mage_Rss_Model_Session
/customer/account/loginPost/  Mage_Core_Model_Session
/customer/account/loginPost/  Mage_Reports_Model_Session
/customer/account/logout/     Mage_Reports_Model_Session
/catalog/product/view/…       Mage_Reports_Model_Session
/catalog/product/view/…       Mage_Tag_Model_Session

UPDATE 2: sessions are stored in files and cleaned up by PHP session garbage collector, whether this is a good choice or not is out of the scope of this question.

Answer 1

After some advanced debugging, session tracing and thinking about all that magic I was able to reproduce the problem and understand the reason for it. I prepared a little timing illustration, you can see it below.

• red flag is the moment of user login and session creation
• blue flag is the moment when user opens catalog page, let's assume it is a category page which is opened.
• green flag is the moment where user submits the order (/sales/order/save/... request)

Here is how to reproduce:

1. Before you start: Set your PHP session timeout and Magento cookie timeout both to be 1440 which is a default PHP value.
2. Kill all your cookies or open the incognito tab.
3. Go to your Magento shop and login (see Flag 1)
4. Go through catalog and add some products to the cart (Flag 2)
5. Go through the checkout and submit an order. Note the time when you did it. (Flag 3)
6. Go through catalog and add some products to the cart (Flag 4)
7. Keep refreshing your cart page or going through catalog pages so long that the timeout which you have configured for magento cookies expires (Flags 5-6). Note that time between Flag 7 and Flag 3 should be bigger than the cookie timeout.
8. Go through the checkout and submit an order (Flag 7). The order submission will fail due to the exception described in my question above.

Reason:

There are certain sessions which are only instantiated on given requests, e.g. Mage_Rss_Model_Session is only instantiated during the actual checkout and not while browsing through catalog. At the same time session expiry timestamp is only set when session was instantiated. That means that if there was enough time between two checkouts and the session was not killed meanwhile (because user logged out or cookie expired) the new Magento code will consider that session as not passing validation and will throw an exception, which sounds somehow strange to me.

How to fix:

Well, I have few options:

1. Wait till Magento reacts on that and reconsiders that code.
2. Remove this code meanwhile.
3. Try setting Magento cookie timeout to 0 if that is an option for you.

How did I figure it out:

1. I started with adding the following to the original code of Mage_Core_Model_Session_Abstract_Varien

   Mage::log(
       sprintf(
           'useValidateSessionExpire fail "%s" "%d" "%d" "%s" "%s" "%s"',
           print_r($sessionData[self::VALIDATOR_SESSION_EXPIRE_TIMESTAMP], 1),
           time(),
           $this->_time,
           get_class($this),
           session_name(),
           session_id()
       ),
       Zend_Log::DEBUG,
       'session-validation.log',
       true
   );
   

   it gave me a good insight about affected classes and their correlation and how much session were expired. But that was not explaining why it happens and which user actions lead to the problem.

2. Then I started thinking on how can I trace all changes to session data and came across this question https://superuser.com/questions/368231/automatic-versioning-upon-file-change-modify-create-delete I decided to give a try to git and incron combination, but after I implemented it and tested in sandbox, I realized that I will run out of disk space really fast in production.

3. I decided to build a small PHP script which will decode session data and write logs for each sesssion. This script was called by incron

   <?php
   //log-session-data-change.php
   
   $sessionLogStoragePath = '/var/www/html/logged-session-storage/';
   
   $sessionFilePath = $argv[1];
   $sessionOperationType = $argv[2];
   $sessionFileName = basename($sessionFilePath);
   
   session_start();
   session_decode(file_get_contents($sessionFilePath));
   
   $logString = sprintf(
     '"%s","%s","%s",""' . PHP_EOL,
     date(DateTime::COOKIE),
     $sessionOperationType,
     $sessionFileName
   );
   
   if (file_exists($sessionFilePath)) {
     session_start();
     session_decode(file_get_contents($sessionFilePath));
   
     foreach ($_SESSION as $name => $data) {
       $value = '<empty>';
       if (isset($data['_session_validator_data']) && isset($data['_session_validator_data']['session_expire_timestamp'])) {
         $value = $data['_session_validator_data']['session_expire_timestamp'];
       }
       $logString .= sprintf(
         '"","","","%s","%s"' . PHP_EOL,
         $name,
         $value
       );
     }
   }
   
   file_put_contents($sessionLogStoragePath . $sessionFileName, $logString, FILE_APPEND);
   

   and here is the corresponding incrontab entry

   /var/www/html/magento-doc-root/var/session IN_MODIFY,IN_CREATE,IN_DELETE,IN_MOVE /usr/bin/php /var/www/html/log-session-data-change.php $@/$# $%
   

   sample output

   "Wednesday, 05-Apr-2017 18:09:06 CEST","IN_MODIFY","sess_94rfglnua0phncmp98hbr3k524",""
   "","","","core","1491408665"
   "","","","customer_base","1491408665"
   "","","","catalog","1491408665"
   "","","","checkout","1491408665"
   "","","","reports","1491408494"
   "","","","store_default","1491408665"
   "","","","rss","1491408524"
   "","","","admin","1491408524"
   

P.S.:

Current versions of both

skin/frontend/enterprise/default/js/opcheckout.js 
src/skin/frontend/base/default/js/opcheckout.js

are not able to handle the exception above during the AJAX request. They display literally nothing to the user, while user effectively gets logged out!

P.P.S.:

apparently Magento CE 1.9.3.x versions are also affected, see https://github.com/OpenMage/magento-mirror/blame/magento-1.9/app/code/core/Mage/Core/Model/Session/Abstract/Varien.php

P.P.P.S.:

When I said "Remove this code meanwhile." I meant excluding the following block

if ($this->useValidateSessionExpire()
    && isset($sessionData[self::VALIDATOR_SESSION_EXPIRE_TIMESTAMP])
    && $sessionData[self::VALIDATOR_SESSION_EXPIRE_TIMESTAMP] < time() ) {
    return false;
} else {
    $this->_data[self::VALIDATOR_KEY][self::VALIDATOR_SESSION_EXPIRE_TIMESTAMP]
        = $validatorData[self::VALIDATOR_SESSION_EXPIRE_TIMESTAMP];
}

you can do that with so many ways, including:

1. Simply deleting that bit from the file
2. Commenting it out
3. Returning before it
4. Making $this->useValidateSessionExpire() return true
5. ...
6. It is programming - be creative ;)

Answer 2

6. It is programming - be creative ;)

Another way to fix this (and improve session validation)

ColinM @ https://github.com/OpenMage/magento-lts

The session code currently stores the session validator data within every namespace and also validates it every time the namespace is inited. This is bad because:

1. Extremely inefficient of session storage space. The validator data often comprises over 50% of the space used by a namespace and when there are many namespaces this adds up to a ton of waste. Session storage can be cut drastically with this patch and when using an in-memory storage like Redis or Memcached that matters a lot.
2. Inefficient of compute cycles since multiple namespaces means multiple validations and there is no good reason for these to differ from each other.
3. Actually creates bugs such as #394 where the validator data is updated on some requests but not others (so it can differ but shouldn't). I haven't tested but I believe this will also fix this issue.

diff --git a/app/code/core/Mage/Core/Model/Session/Abstract/Varien.php b/app/code/core/Mage/Core/Model/Session/Abstract/Varien.php
index 45d736543..ea6b464f1 100644
--- a/app/code/core/Mage/Core/Model/Session/Abstract/Varien.php
+++ b/app/code/core/Mage/Core/Model/Session/Abstract/Varien.php
@@ -35,6 +35,9 @@ class Mage_Core_Model_Session_Abstract_Varien extends Varien_Object
     const VALIDATOR_SESSION_EXPIRE_TIMESTAMP    = 'session_expire_timestamp';
     const SECURE_COOKIE_CHECK_KEY               = '_secure_cookie_check';

+    /** @var bool Flag true if session validator data has already been evaluated */
+    protected static $isValidated = FALSE;
+
     /**
      * Map of session enabled hosts
      * @example array('host.name' => true)
@@ -406,16 +409,21 @@ public function getValidateHttpUserAgentSkip()
     /**
      * Validate session
      *
-     * @param string $namespace
+     * @throws Mage_Core_Model_Session_Exception
      * @return Mage_Core_Model_Session_Abstract_Varien
      */
     public function validate()
     {
-        if (!isset($this->_data[self::VALIDATOR_KEY])) {
-            $this->_data[self::VALIDATOR_KEY] = $this->getValidatorData();
+        // Backwards compatibility with legacy sessions (validator data stored per-namespace)
+        if (isset($this->_data[self::VALIDATOR_KEY])) {
+            $_SESSION[self::VALIDATOR_KEY] = $this->_data[self::VALIDATOR_KEY];
+            unset($this->_data[self::VALIDATOR_KEY]);
+        }
+        if (!isset($_SESSION[self::VALIDATOR_KEY])) {
+            $_SESSION[self::VALIDATOR_KEY] = $this->getValidatorData();
         }
         else {
-            if (!$this->_validate()) {
+            if ( ! self::$isValidated && ! $this->_validate()) {
                 $this->getCookie()->delete(session_name());
                 // throw core session exception
                 throw new Mage_Core_Model_Session_Exception('');
@@ -432,8 +440,9 @@ public function validate()
      */
     protected function _validate()
     {
-        $sessionData = $this->_data[self::VALIDATOR_KEY];
+        $sessionData = $_SESSION[self::VALIDATOR_KEY];
         $validatorData = $this->getValidatorData();
+        self::$isValidated = TRUE; // Only validate once since the validator data is the same for every namespace

         if ($this->useValidateRemoteAddr()
                 && $sessionData[self::VALIDATOR_REMOTE_ADDR_KEY] != $validatorData[self::VALIDATOR_REMOTE_ADDR_KEY]) {
@@ -444,10 +453,8 @@ protected function _validate()
             return false;
         }

-        $sessionValidateHttpXForwardedForKey = $sessionData[self::VALIDATOR_HTTP_X_FORVARDED_FOR_KEY];
-        $validatorValidateHttpXForwardedForKey = $validatorData[self::VALIDATOR_HTTP_X_FORVARDED_FOR_KEY];
         if ($this->useValidateHttpXForwardedFor()
-            && $sessionValidateHttpXForwardedForKey != $validatorValidateHttpXForwardedForKey ) {
+                && $sessionData[self::VALIDATOR_HTTP_X_FORVARDED_FOR_KEY] != $validatorData[self::VALIDATOR_HTTP_X_FORVARDED_FOR_KEY]) {
             return false;
         }
         if ($this->useValidateHttpUserAgent()

^{Source: https://github.com/OpenMage/magento-lts/commit/de06e671c09b375605a956e100911396822e276a}

---

Update:

Fix for web/session/use_http_x_forwarded_for option disabled option ... https://github.com/OpenMage/magento-lts/pull/457/commits/ec8128b4605e82406679c3cd81244ddf3878c379

Answer 3

How are you storing sessions? (i.e. in var/session/ or in the DB, or using other caching engines such as Redis or Memcached)

Whichever it is you're using, be sure your write permissions are correct on var/session/ (typically set to 755 for dirs and 644 for files), or if you're using Redis or Memcache, make sure your connection and timeout settings are good for those.

Inchoo has a good tutorial for Redis: http://inchoo.net/magento/using-redis-cache-backend-and-session-storage-in-magento/

If using Memcache, checkout this article (it references v1.10, but shouldn't be much different): http://www.magestore.com/magento/magento-sessions-disappearing-with-memcache-turned-on.html

Also, if you happen to be using something like Varnish, there have been issues in the past with sessions where hole-punching certain pages was needed.

Finally, if you're using the file system for your sessions, you might find relief by simply switching the <session_save> node in your local.xml to "db" instead of "files".

From this <session_save><![CDATA[files]]></session_save>

To this <session_save><![CDATA[db]]></session_save>

Answer 4

The detail by Anton Boritskiy is fantastic. But instead of excluding this block you could make a local copy so you ain't editing the core and rewrite the block like:

if ($this->useValidateSessionExpire() ) {
    // If the VALIDATOR_SESSION_EXPIRE_TIMESTAMP key is not set, do it now
    if( !isset($sessionData[self::VALIDATOR_SESSION_EXPIRE_TIMESTAMP]) ) {
        // $this->_data is a reference to the $_SESSION variable so it will be automatically modified
        $this->_data[self::VALIDATOR_SESSION_EXPIRE_TIMESTAMP] = time() + $this->getCookie()->getLifetime();
        return true;
    } elseif ( $sessionData[self::VALIDATOR_SESSION_EXPIRE_TIMESTAMP] < time() ) {
        return false;
    }
} else {
    $this->_data[self::VALIDATOR_KEY][self::VALIDATOR_SESSION_EXPIRE_TIMESTAMP]
        = $validatorData[self::VALIDATOR_SESSION_EXPIRE_TIMESTAMP];
}

This assures that the comparison between time() and the session_expire_timestamp is only executed when the key exists and that when a session is found that does not have the key (i.e. a pre 1.9.3 session) the key is added.