Magento Cron TwoLevel Cache Issue: PDOException SQLSTATE[42S22] & Zend_Db_Statement_Exception SQLSTATE[42000] exceptions

There I was drinking my coffee when a customer complained about a problem: no order emails were being sent from his Magento shop.

My first thought was “This is going to be easy, my coffee won’t even get cold. It must be the change introduced in 1.9.1. and maybe the cron is not setup correctly”.

I have never been so wrong in my life.

Checking the error logs I found a strange error that made me cry because I knew instantly that I would have to go into the CORE and debug the life out of it:

exception 'PDOException' with message 'SQLSTATE[42000]: Syntax error or access violation: 1064 You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'WHERE (message_id='23')' at line 1' in /magento/lib/Zend/Db/Statement/Pdo.php:228

Next

exception 'Zend_Db_Statement_Exception' with message 'SQLSTATE[42000]: Syntax error or access violation: 1064 You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'WHERE (message_id='23')' at line 1, query was: UPDATE `core_email_queue` SET WHERE (message_id='23')' in /magento/lib/Zend/Db/Statement/Pdo.php:235

I also found another strange error with the cron.php entry point and my spidey senses started tingling. I was on to something.

exception 'PDOException' with message 'SQLSTATE[42S22]: Column not found: 1054 Unknown column 'main_table.data' in 'field list'' in /magento/lib/Zend/Db/Statement/Pdo.php:228

Next

exception 'Zend_Db_Statement_Exception' with message 'SQLSTATE[42S22]: Column not found: 1054 Unknown column 'main_table.data' in 'field list', query was: SELECT `main_table`.`data`, `main_table`.`lifetime`, `main_table`.`expire`, `main_table`.`priority`, `additional_table`.* FROM `eav_attribute` AS `main_table`
INNER JOIN `catalog_eav_attribute` AS `additional_table` ON additional_table.attribute_id = main_table.attribute_id WHERE (main_table.entity_type_id = 4)' in /magento/lib/Zend/Db/Statement/Pdo.php:235

From the errors, it seems that there was an issue with column names, in both the UPDATE and the SELECT queries.

In Magento, before executing database queries, the columns get checked against the column descriptions for the respective table.
For models extending Mage_Core_Model_Resource_Db_Abstract, for example, calling the save method will call:

protected function _prepareDataForSave(Mage_Core_Model_Abstract $object)
{
    return $this->_prepareDataForTable($object, $this->getMainTable());
}

which then calls Mage_Core_Model_Resource_Abstract::_prepareDataForTable

protected function _prepareDataForTable(Varien_Object $object, $table)
{
    $data = array();
    $fields = $this->_getWriteAdapter()->describeTable($table);
    foreach (array_keys($fields) as $field) {
        if ($object->hasData($field)) {
            $fieldValue = $object->getData($field);
            if ($fieldValue instanceof Zend_Db_Expr) {
                $data[$field] = $fieldValue;
            } else {
                if (null !== $fieldValue) {
                    $fieldValue = $this->_prepareTableValueForSave($fieldValue, $fields[$field]['DATA_TYPE']);
                    $data[$field] = $this->_getWriteAdapter()->prepareColumnValue($fields[$field], $fieldValue);
                } else if (!empty($fields[$field]['NULLABLE'])) {
                    $data[$field] = null;
                }
            }
        }
    }
    return $data;
}

If something was wrong here, it was related to what the $fields variable contained.
Which, in turn, lead me to the main problem in my quest: the Varien_Db_Adapter_Pdo_Mysql::describeTable method.

public function describeTable($tableName, $schemaName = null)
{
    $cacheKey = $this->_getTableName($tableName, $schemaName);
    $ddl = $this->loadDdlCache($cacheKey, self::DDL_DESCRIBE);
    if ($ddl === false) {
        $ddl = array_map(
            array(
                $this,
                'decorateTableInfo'
            ),
            parent::describeTable($tableName, $schemaName)
        );
        /**
        * Remove bug in some MySQL versions, when int-column without default value is described as:
        * having default empty string value
        */
        $affected = array('tinyint', 'smallint', 'mediumint', 'int', 'bigint');
        foreach ($ddl as $key => $columnData) {
            if (($columnData['DEFAULT'] === '') && (array_search($columnData['DATA_TYPE'], $affected) !== FALSE)) {
                $ddl[$key]['DEFAULT'] = null;
            }
        }
        $this->saveDdlCache($cacheKey, self::DDL_DESCRIBE, $ddl);
    }

    return $ddl;
}

In order not to execute the DESCRIBE query each time, Magento caches the DDL info for the tables.

The errors I found, happened when loading the DDL info from the cache.

public function loadDdlCache($tableCacheKey, $ddlType)
{
    if (!$this->_isDdlCacheAllowed) {
        return false;
    }
    if (isset($this->_ddlCache[$ddlType][$tableCacheKey])) {
        return $this->_ddlCache[$ddlType][$tableCacheKey];
    }

    if ($this->_cacheAdapter instanceof Zend_Cache_Core) {
        $cacheId = $this->_getCacheId($tableCacheKey, $ddlType);
        $data = $this->_cacheAdapter->load($cacheId);
        if ($data !== false) {
            $data = unserialize($data);
            $this->_ddlCache[$ddlType][$tableCacheKey] = $data;
        }
        return $data;
    }

    return false;
}

The data loaded by the cache adapter and unserialized in this method looked something like this:

(
[data] => a:17:{s:12:"attribute_id";a:14:{s:11:"SCHEMA_NAME";N;s:10:"TABLE_NAME";s:13:"eav_attribute";s:11:"COLUMN_NAME";s:12:"attribute_id"; ...
[lifetime] => 7200
[expire] => 1458642937
[priority] => 8
)

This info was loaded from the var/cache/mage–e/mage—MAGE_DB_PDO_MYSQL_DDL_eav_attribute_1 file:

a:4:{s:4:"data";s:6028:"a:17:{s:12:"attribute_id";a:14:{s:11:"SCHEMA_NAME";N;s:10:"TABLE_NAME";s:13:"eav_attribute"; [...]

This was a problem since this data was then used, assuming the keys of this array were table columns, which they were not :).

A few logs and coffees after, I found that Zend_Cache_Core was saving data into the DDL cache files, sometimes by calling Zend_Cache_Backend_File::save() directly and sometimes by calling Zend_Cache_Backend_TwoLevels::save() which then was responsible for calling Zend_Cache_Backend_File::save().

The two levels cache from Zend uses the _prepareData method to prepare a serialized array to store datas and metadatas information:

private function _prepareData($data, $lifetime, $priority)
{
    $lt = $lifetime;
    if ($lt === null) {
        $lt = 9999999999;
    }
    return serialize(array(
        'data' => $data,
        'lifetime' => $lifetime,
        'expire' => time() + $lt,
        'priority' => $priority
    ));
}

The issue was that when calling the cron or other scripts from the command line, the two level cache was not used. When reading data from the cache files, the data was assumed to be stored without the data, lifetime, expire and priority metadata.

Comparing a request from the browser with a command line request, I found that Mage_Core_Model_Cache::getBackendOptions was returning different options. This server was set to use APC cache, however when the cron was running ini_get(‘apc.enabled’) was false.

Upon checking the php.ini configuration file, the villain revealed itself. In /etc/php5 there were 2 folders: cli and fpm each with his own configuration file.
It seems that even though in fpm/php.ini apc.enabled was 1, in cli/php.ini apc.enabled was 0.

The Magento instance that was run from the command line was not able, thus, to use the APC cache, so it did not use a two-level cache, which led to it not knowing how to correctly read the data from the cache files.

The fpm Magento instance used APC and the two level cache and was saving DDL data into the var/cache folder enclosed in an array with the data, lifetime, expire and priority keys.
When the cron ran and read the DDL cache file, it used the data found there and basically considered for each table, that the columns are data, lifetime, expire and priority.

Changing apc.enabled to 1 in the cli/php.ini configuration file did the trick and solved the issue.