Database columns are not properly cached and lead to mass email sending during cron execution

[func0der]

Preconditions (*)

OpenMage 19.5.0-rc5
MySQL Server: Percona 5.7.35-38

Else there are none that I know of.
Maybe hosting at Mittwald.de 🤷

Steps to reproduce (*)

1. Trigger email sending (for example by placing and order or using the admin interface to trigger order email)
2. Let cron run
3. Trigger an email again

Expected result (*)

1. Email is sent once

Actual result (*)

1. Email is sent a dozen times, because it is not marked as "processed" in the core_email_queue table.
2. Error Message in the log:

   Next Zend_Db_Statement_Exception: 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='23912')' at line 1, query was: UPDATE `core_email_queue` SET  WHERE (message_id='23912') in /html/vendor/shardj/zf1-future/library/Zend/Db/Statement/Pdo.php:235
Stack trace:
#0 /html/webroot/lib/Varien/Db/Statement/Pdo/Mysql.php(98): Zend_Db_Statement_Pdo->_execute(Array)
#1 /html/vendor/shardj/zf1-future/library/Zend/Db/Statement.php(303): Varien_Db_Statement_Pdo_Mysql->_execute(Array)
#2 /html/vendor/shardj/zf1-future/library/Zend/Db/Adapter/Abstract.php(480): Zend_Db_Statement->execute(Array)
#3 /html/vendor/shardj/zf1-future/library/Zend/Db/Adapter/Pdo/Abstract.php(244): Zend_Db_Adapter_Abstract->query('UPDATE `core_em...', Array)
#4 /html/webroot/lib/Varien/Db/Adapter/Pdo/Mysql.php(486): Zend_Db_Adapter_Pdo_Abstract->query('UPDATE `core_em...', Array)
#5 /html/vendor/shardj/zf1-future/library/Zend/Db/Adapter/Abstract.php(636): Varien_Db_Adapter_Pdo_Mysql->query('UPDATE `core_em...', Array)
#6 /html/webroot/app/code/core/Mage/Core/Model/Resource/Db/Abstract.php(439): Zend_Db_Adapter_Abstract->update('core_email_queu...', Array, '(message_id='23...')
#7 /html/webroot/app/code/core/Mage/Core/Model/Abstract.php(328): Mage_Core_Model_Resource_Db_Abstract->save(Object(Mage_Core_Model_Email_Queue))
#8 /html/webroot/app/code/core/Mage/Core/Model/Email/Queue.php(247): Mage_Core_Model_Abstract->save()
#9 /html/webroot/app/code/core/Mage/Cron/Model/Observer.php(319): Mage_Core_Model_Email_Queue->send(Object(Mage_Cron_Model_Schedule))
#10 /html/webroot/app/code/core/Mage/Cron/Model/Observer.php(61): Mage_Cron_Model_Observer->_processJob(Object(Mage_Cron_Model_Schedule), Object(Mage_Core_Model_Config_Element))
#11 /html/webroot/app/code/core/Mage/Core/Model/App.php(1399): Mage_Cron_Model_Observer->dispatch(Object(Varien_Event_Observer))
#12 /html/webroot/app/code/core/Mage/Core/Model/App.php(1377): Mage_Core_Model_App->_callObserverMethod(Object(Mage_Cron_Model_Observer), 'dispatch', Object(Varien_Event_Observer), 'cron_observer')
#13 /html/webroot/app/Mage.php(508): Mage_Core_Model_App->dispatchEvent('default', Array)
#14 /html/webroot/cron.php(71): Mage::dispatchEvent('default')
#15 {main}

Here are the two different cache files of the cron_email_queue table.

First run of cron sending out an email generates this cache file:

array(9) {
  ["message_id"]=>
  array(14) {
    ["SCHEMA_NAME"]=>
    NULL
    ["TABLE_NAME"]=>
    string(16) "core_email_queue"
    ["COLUMN_NAME"]=>
    string(10) "message_id"
    ["COLUMN_POSITION"]=>
    int(1)
    ["DATA_TYPE"]=>
    string(3) "int"
    ["DEFAULT"]=>
    NULL
    ["NULLABLE"]=>
    bool(false)
    ["LENGTH"]=>
    NULL
    ["SCALE"]=>
    NULL
    ["PRECISION"]=>
    NULL
    ["UNSIGNED"]=>
    bool(true)
    ["PRIMARY"]=>
    bool(true)
    ["PRIMARY_POSITION"]=>
    int(1)
    ["IDENTITY"]=>
    bool(true)
  }
  ["entity_id"]=>
  array(14) {
    ["SCHEMA_NAME"]=>
    NULL
    ["TABLE_NAME"]=>
    string(16) "core_email_queue"
    ["COLUMN_NAME"]=>
    string(9) "entity_id"
    ["COLUMN_POSITION"]=>
    int(2)
    ["DATA_TYPE"]=>
    string(3) "int"
    ["DEFAULT"]=>
    NULL
    ["NULLABLE"]=>
    bool(true)
    ["LENGTH"]=>
    NULL
    ["SCALE"]=>
    NULL
    ["PRECISION"]=>
    NULL
    ["UNSIGNED"]=>
    bool(true)
    ["PRIMARY"]=>
    bool(false)
    ["PRIMARY_POSITION"]=>
    NULL
    ["IDENTITY"]=>
    bool(false)
  }
  ["entity_type"]=>
  array(14) {
    ["SCHEMA_NAME"]=>
    NULL
    ["TABLE_NAME"]=>
    string(16) "core_email_queue"
    ["COLUMN_NAME"]=>
    string(11) "entity_type"
    ["COLUMN_POSITION"]=>
    int(3)
    ["DATA_TYPE"]=>
    string(7) "varchar"
    ["DEFAULT"]=>
    NULL
    ["NULLABLE"]=>
    bool(true)
    ["LENGTH"]=>
    string(3) "128"
    ["SCALE"]=>
    NULL
    ["PRECISION"]=>
    NULL
    ["UNSIGNED"]=>
    NULL
    ["PRIMARY"]=>
    bool(false)
    ["PRIMARY_POSITION"]=>
    NULL
    ["IDENTITY"]=>
    bool(false)
  }
  ["event_type"]=>
  array(14) {
    ["SCHEMA_NAME"]=>
    NULL
    ["TABLE_NAME"]=>
    string(16) "core_email_queue"
    ["COLUMN_NAME"]=>
    string(10) "event_type"
    ["COLUMN_POSITION"]=>
    int(4)
    ["DATA_TYPE"]=>
    string(7) "varchar"
    ["DEFAULT"]=>
    NULL
    ["NULLABLE"]=>
    bool(true)
    ["LENGTH"]=>
    string(3) "128"
    ["SCALE"]=>
    NULL
    ["PRECISION"]=>
    NULL
    ["UNSIGNED"]=>
    NULL
    ["PRIMARY"]=>
    bool(false)
    ["PRIMARY_POSITION"]=>
    NULL
    ["IDENTITY"]=>
    bool(false)
  }
  ["message_body_hash"]=>
  array(14) {
    ["SCHEMA_NAME"]=>
    NULL
    ["TABLE_NAME"]=>
    string(16) "core_email_queue"
    ["COLUMN_NAME"]=>
    string(17) "message_body_hash"
    ["COLUMN_POSITION"]=>
    int(5)
    ["DATA_TYPE"]=>
    string(7) "varchar"
    ["DEFAULT"]=>
    NULL
    ["NULLABLE"]=>
    bool(false)
    ["LENGTH"]=>
    string(2) "64"
    ["SCALE"]=>
    NULL
    ["PRECISION"]=>
    NULL
    ["UNSIGNED"]=>
    NULL
    ["PRIMARY"]=>
    bool(false)
    ["PRIMARY_POSITION"]=>
    NULL
    ["IDENTITY"]=>
    bool(false)
  }
  ["message_body"]=>
  array(14) {
    ["SCHEMA_NAME"]=>
    NULL
    ["TABLE_NAME"]=>
    string(16) "core_email_queue"
    ["COLUMN_NAME"]=>
    string(12) "message_body"
    ["COLUMN_POSITION"]=>
    int(6)
    ["DATA_TYPE"]=>
    string(10) "mediumtext"
    ["DEFAULT"]=>
    NULL
    ["NULLABLE"]=>
    bool(false)
    ["LENGTH"]=>
    NULL
    ["SCALE"]=>
    NULL
    ["PRECISION"]=>
    NULL
    ["UNSIGNED"]=>
    NULL
    ["PRIMARY"]=>
    bool(false)
    ["PRIMARY_POSITION"]=>
    NULL
    ["IDENTITY"]=>
    bool(false)
  }
  ["message_parameters"]=>
  array(14) {
    ["SCHEMA_NAME"]=>
    NULL
    ["TABLE_NAME"]=>
    string(16) "core_email_queue"
    ["COLUMN_NAME"]=>
    string(18) "message_parameters"
    ["COLUMN_POSITION"]=>
    int(7)
    ["DATA_TYPE"]=>
    string(4) "text"
    ["DEFAULT"]=>
    NULL
    ["NULLABLE"]=>
    bool(false)
    ["LENGTH"]=>
    NULL
    ["SCALE"]=>
    NULL
    ["PRECISION"]=>
    NULL
    ["UNSIGNED"]=>
    NULL
    ["PRIMARY"]=>
    bool(false)
    ["PRIMARY_POSITION"]=>
    NULL
    ["IDENTITY"]=>
    bool(false)
  }
  ["created_at"]=>
  array(14) {
    ["SCHEMA_NAME"]=>
    NULL
    ["TABLE_NAME"]=>
    string(16) "core_email_queue"
    ["COLUMN_NAME"]=>
    string(10) "created_at"
    ["COLUMN_POSITION"]=>
    int(8)
    ["DATA_TYPE"]=>
    string(9) "timestamp"
    ["DEFAULT"]=>
    NULL
    ["NULLABLE"]=>
    bool(true)
    ["LENGTH"]=>
    NULL
    ["SCALE"]=>
    NULL
    ["PRECISION"]=>
    NULL
    ["UNSIGNED"]=>
    NULL
    ["PRIMARY"]=>
    bool(false)
    ["PRIMARY_POSITION"]=>
    NULL
    ["IDENTITY"]=>
    bool(false)
  }
  ["processed_at"]=>
  array(14) {
    ["SCHEMA_NAME"]=>
    NULL
    ["TABLE_NAME"]=>
    string(16) "core_email_queue"
    ["COLUMN_NAME"]=>
    string(12) "processed_at"
    ["COLUMN_POSITION"]=>
    int(9)
    ["DATA_TYPE"]=>
    string(9) "timestamp"
    ["DEFAULT"]=>
    NULL
    ["NULLABLE"]=>
    bool(true)
    ["LENGTH"]=>
    NULL
    ["SCALE"]=>
    NULL
    ["PRECISION"]=>
    NULL
    ["UNSIGNED"]=>
    NULL
    ["PRIMARY"]=>
    bool(false)
    ["PRIMARY_POSITION"]=>
    NULL
    ["IDENTITY"]=>
    bool(false)
  }
}

Second run of cron sending out an email generates this cache file:

array(4) {
  ["data"]=>
  string(3164) "a:9:{s:10:"message_id";a:14:{s:11:"SCHEMA_NAME";N;s:10:"TABLE_NAME";s:16:"core_email_queue";s:11:"COLUMN_NAME";s:10:"message_id";s:15:"COLUMN_POSITION";i:1;s:9:"DATA_TYPE";s:3:"int";s:7:"DEFAULT";N;s:8:"NULLABLE";b:0;s:6:"LENGTH";N;s:5:"SCALE";N;s:9:"PRECISION";N;s:8:"UNSIGNED";b:1;s:7:"PRIMARY";b:1;s:16:"PRIMARY_POSITION";i:1;s:8:"IDENTITY";b:1;}s:9:"entity_id";a:14:{s:11:"SCHEMA_NAME";N;s:10:"TABLE_NAME";s:16:"core_email_queue";s:11:"COLUMN_NAME";s:9:"entity_id";s:15:"COLUMN_POSITION";i:2;s:9:"DATA_TYPE";s:3:"int";s:7:"DEFAULT";N;s:8:"NULLABLE";b:1;s:6:"LENGTH";N;s:5:"SCALE";N;s:9:"PRECISION";N;s:8:"UNSIGNED";b:1;s:7:"PRIMARY";b:0;s:16:"PRIMARY_POSITION";N;s:8:"IDENTITY";b:0;}s:11:"entity_type";a:14:{s:11:"SCHEMA_NAME";N;s:10:"TABLE_NAME";s:16:"core_email_queue";s:11:"COLUMN_NAME";s:11:"entity_type";s:15:"COLUMN_POSITION";i:3;s:9:"DATA_TYPE";s:7:"varchar";s:7:"DEFAULT";N;s:8:"NULLABLE";b:1;s:6:"LENGTH";s:3:"128";s:5:"SCALE";N;s:9:"PRECISION";N;s:8:"UNSIGNED";N;s:7:"PRIMARY";b:0;s:16:"PRIMARY_POSITION";N;s:8:"IDENTITY";b:0;}s:10:"event_type";a:14:{s:11:"SCHEMA_NAME";N;s:10:"TABLE_NAME";s:16:"core_email_queue";s:11:"COLUMN_NAME";s:10:"event_type";s:15:"COLUMN_POSITION";i:4;s:9:"DATA_TYPE";s:7:"varchar";s:7:"DEFAULT";N;s:8:"NULLABLE";b:1;s:6:"LENGTH";s:3:"128";s:5:"SCALE";N;s:9:"PRECISION";N;s:8:"UNSIGNED";N;s:7:"PRIMARY";b:0;s:16:"PRIMARY_POSITION";N;s:8:"IDENTITY";b:0;}s:17:"message_body_hash";a:14:{s:11:"SCHEMA_NAME";N;s:10:"TABLE_NAME";s:16:"core_email_queue";s:11:"COLUMN_NAME";s:17:"message_body_hash";s:15:"COLUMN_POSITION";i:5;s:9:"DATA_TYPE";s:7:"varchar";s:7:"DEFAULT";N;s:8:"NULLABLE";b:0;s:6:"LENGTH";s:2:"64";s:5:"SCALE";N;s:9:"PRECISION";N;s:8:"UNSIGNED";N;s:7:"PRIMARY";b:0;s:16:"PRIMARY_POSITION";N;s:8:"IDENTITY";b:0;}s:12:"message_body";a:14:{s:11:"SCHEMA_NAME";N;s:10:"TABLE_NAME";s:16:"core_email_queue";s:11:"COLUMN_NAME";s:12:"message_body";s:15:"COLUMN_POSITION";i:6;s:9:"DATA_TYPE";s:10:"mediumtext";s:7:"DEFAULT";N;s:8:"NULLABLE";b:0;s:6:"LENGTH";N;s:5:"SCALE";N;s:9:"PRECISION";N;s:8:"UNSIGNED";N;s:7:"PRIMARY";b:0;s:16:"PRIMARY_POSITION";N;s:8:"IDENTITY";b:0;}s:18:"message_parameters";a:14:{s:11:"SCHEMA_NAME";N;s:10:"TABLE_NAME";s:16:"core_email_queue";s:11:"COLUMN_NAME";s:18:"message_parameters";s:15:"COLUMN_POSITION";i:7;s:9:"DATA_TYPE";s:4:"text";s:7:"DEFAULT";N;s:8:"NULLABLE";b:0;s:6:"LENGTH";N;s:5:"SCALE";N;s:9:"PRECISION";N;s:8:"UNSIGNED";N;s:7:"PRIMARY";b:0;s:16:"PRIMARY_POSITION";N;s:8:"IDENTITY";b:0;}s:10:"created_at";a:14:{s:11:"SCHEMA_NAME";N;s:10:"TABLE_NAME";s:16:"core_email_queue";s:11:"COLUMN_NAME";s:10:"created_at";s:15:"COLUMN_POSITION";i:8;s:9:"DATA_TYPE";s:9:"timestamp";s:7:"DEFAULT";N;s:8:"NULLABLE";b:1;s:6:"LENGTH";N;s:5:"SCALE";N;s:9:"PRECISION";N;s:8:"UNSIGNED";N;s:7:"PRIMARY";b:0;s:16:"PRIMARY_POSITION";N;s:8:"IDENTITY";b:0;}s:12:"processed_at";a:14:{s:11:"SCHEMA_NAME";N;s:10:"TABLE_NAME";s:16:"core_email_queue";s:11:"COLUMN_NAME";s:12:"processed_at";s:15:"COLUMN_POSITION";i:9;s:9:"DATA_TYPE";s:9:"timestamp";s:7:"DEFAULT";N;s:8:"NULLABLE";b:1;s:6:"LENGTH";N;s:5:"SCALE";N;s:9:"PRECISION";N;s:8:"UNSIGNED";N;s:7:"PRIMARY";b:0;s:16:"PRIMARY_POSITION";N;s:8:"IDENTITY";b:0;}}"
  ["lifetime"]=>
  int(7200)
  ["expire"]=>
  int(1689469462)
  ["priority"]=>
  int(8)
}

I have unserialized the data so it is easier to digest.
But apparently something is writing data in a completely different structure into the files.

As I can not reliably reproduce this problem locally, I sadly do not have any more information to give to you.
Locally I have the result WITHOUT data.

Do cron and web application use different cache versions?

[pquerner]

Probably needs more info, like

OpenMage version, Mysql Server version (any different settings?) etc.

[func0der]

Oh. I am sorry, I put those in but then re-arranged the whole post.
This installation is nothing special disregarding the fact, that it is currently broken :D

[pquerner]

Whats the exact mysql error your database complains?

[sreichel]

UPDATE core_email_queue SET WHERE (message_id='23912')

Set-part is empty?

[fballiano]

I'm on the main branch, php82, mysql8, caches all enabled (also with all disabled I've the same behaviour), 3 mails in core_email_queue:

after running cron.php they get marked as processed:

[ADDISON74]

I tried to replicate this issue without any luck, using a fresh instance of the following

Windows 10, DDEV + WSL (Apache + PHP 8.2 + MariaDB)
OpenMage 20.1.0-rc7 (using git clone)
Magento Sample Data (using ddev openmage-install)

I truncated before running the tests both cron_schedule and core_email_queue tables. I placed an order. Cron is running then the email is triggered by MailHog

This is a screenshot related to the table content. The request was processed (the last column).

Possible solutions, taking in consideration the OpenMage file system is untouched:

1. Empty the table core_email_queue (TRUNCATE), or
2. Delete the table core_email_queue and re-create it

If not working you have missing or modified files. As Sven pointed out above the query is wrong.

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='23912')' at line 1, 
query was: UPDATE `core_email_queue` SET  WHERE (message_id='23912')

UPDATE statement has this syntax

UPDATE table_name
SET column1 = value1, column2 = value2, ...
WHERE condition;

In your case SET has missing arguments.

[func0der]

I found it out. And I am really sorry to have wasted your time.

The key information here is actually really something I added kinda ironically.

Maybe hosting at Mittwald.de 🤷

They have an Apache2 + FPM setup. Mix in a little OPCache inside there and a symlink release setup.

Old release: current -> release-18
New release: current -> release-19

Apache2 coming in being configured to go to current.
The error log of the cron was not a good insight.
The error log of the web requests gave more insight (with other exceptions):

#13 */html/release-19*/webroot/app/..... 
#14 */html/release-18*/webroot/index.php(88): Mage::run($mageRunCode, $mageRunType);

As we see here, the request starts inrelease-18 and then moves onward to release-19.
The opcache then bounced around between 18 and 19.
The cache got rewritten at times, but it was obviously not compatible with each other, which lead to the broken sql query.

The core_email_queue was properly the only table that got used by the cron and the web application and therefor caused this catastrophic behavior.

After clearing the opcache with opcache_reset() within the FPM process, it worked properly. And also every other exception in the log disappeared (including those I have mentioned here: #3381 (comment)) WHY?!?!? Idk :D Maybe the new OpenMage version handles those exceptions differently now.

So, what have we learned:

• If you release a new version of your software: clear the opcache (fpm reload, cachetool, whatever)
• Try to use the realpath when communicating with FPM, not weird symlinks
  • This is not really possible with Apache
  • With nginx use $realpath: fastcgi_param SCRIPT_FILENAME $realpath_root/[filename]
• Follow your ironically added information, if they seem like a solid hint :D

Regarding the cache structure change
I jumped from OpenMage 19.4.15 to 19.5.0-rc5.
In between those releases the file cache structure seems to have changed.

Since the cache is usually not required to sustain over releases, is it not considering this to be a breaking change, which should be version 20? 🤔