Session Validation Failure in Magento 1 EE v1.14.3.x and CE 1.9.3.x – How to Fix

bugee-1.14ee-1.14.3.0magento1.9.3session

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.

Best Answer

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:

Before you start: Set your PHP session timeout and Magento cookie timeout both to be 1440 which is a default PHP value.
Kill all your cookies or open the incognito tab.
Go to your Magento shop and login (see Flag 1)
Go through catalog and add some products to the cart (Flag 2)
Go through the checkout and submit an order. Note the time when you did it. (Flag 3)
Go through catalog and add some products to the cart (Flag 4)
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.
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:

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

How did I figure it out:

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.

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.

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:

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

Related Solutions

Magento 2 – Syncing Backend and Frontend State/Cache

I had a similar problem: I wanted the mini-cart component to refresh after I sent an Ajax request to add an item the cart.

It actually works quite nicely if you just remember some points:

Declare which page sections need to be updated after an Ajax call, in etc/frontend/sections.xml of your module.
Use jQuery.post() to send your Ajax request. It may be a POST or a PUT request, just not GET.
And it must be through jQuery, not Prototype or vanilla JS, because it is jQuery's 'ajaxComplete' event that plays an essential role.
prepend the Ajax url with a base-url (do not just start with /)

Here is my sections.xml (xyz is the name of our customer):

<?xml version="1.0"?>
<config xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
        xsi:noNamespaceSchemaLocation="urn:magento:module:Magento_Customer:etc/sections.xsd">
    <action name="xyz-ajax/cart/add">
        <section name="cart"/>
    </action>
</config>

Here, 'xyz-ajax/cart/add' is according to the format '[frontName]/[ActionPath]/[ActionName]'. The xml tells Magento to update 'cart' after ajax call "xyz-ajax/cart/add" has completed.

This is my template (.phtml) code:

<script type="text/javascript">
    require(['jquery', 'BigBridge_XYZ/option_selector'], function($, optionSelect) {
        optionSelect.create(<?= json_encode($componentData) ?>, $);
    })
</script>

and this is the JS code that sends the Ajax request:

function requestComplete(responseData) { }

$.post(baseUrl + 'xyz-ajax/cart/add/cf/' + configurableProductId + '/simple/' + item.simpleProductId + '/amount/' + item.amount, requestComplete);

What happens in the process?

Every time your script sends an Ajax POST (or PUT) request to the server via jQuery, and it returns, jQuery sends an 'ajaxComplete' event. This event is handled by a handler in module-customer/view/frontend/web/js/customer-data.js. This handler checks which page-sections depend on the Ajax call (from your sections.xml) and invalidates them. These will be updated.

Sources:

Magento – Magento 1.9.3 magento Mage registry key “_singleton/customer/session” already exists

This is happened because you have already registered the same key name _singleton/customer/session.

File: app/Mage.php/ you can see below function in this file

public static function register($key, $value, $graceful = false)
{
    if (isset(self::$_registry[$key])) {
        if ($graceful) {
            return;
        }
        self::throwException('Mage registry key "'.$key.'" already exists');
    }
    self::$_registry[$key] = $value;
}

We can see that any object or value we’re storing in the registry is ultimately being stored in the static $_registry class variable. We can also see that before storing the value, Magento checks if it’s already set. If so, Magento will either throw an Exception (the default behavior) or gracefully return null

its already set with other value

Finally, if you want to make you variable unavailable, you can use the unregister method to remove it from the registry.

Mage::unregister('method_name');

Try this too

php -f compiler.php clear
php -f compiler.php disable

this will disable the compilation and will clear the files, after this delete content of var/cache/* and var/session/* by this command:

rm -Rf var/cache/*
rm -Rf var/session/*

Best Answer

Related Solutions

Magento 2 – Syncing Backend and Frontend State/Cache

Magento – Magento 1.9.3 magento Mage registry key “_singleton/customer/session” already exists

Related Topic