Log spill / recursive error message when unable to connect to DB
ISPConfig version is 3.1.2. There is an issue with recursive log messages leading to a huge /var/log/ispconfig/cron.log
file. Here, 0.8 GiB accumulated in 30 minutes. Namely if for any reason establishing a database connection is impossible for a time, I get the following sequence of messages in that cron.log
.
Thu Feb 16 02:49:21 CET 2017 PHP Warning: mysqli_ping() expects parameter 1 to be mysqli, null given in /usr/local/ispconfig/server/lib/classes/db_mysql.inc.php on line 198
Thu Feb 16 02:49:21 CET 2017 PHP Warning: mysqli_query() expects parameter 1 to be mysqli, null given in /usr/local/ispconfig/server/lib/classes/db_mysql.inc.php on line 182
Thu Feb 16 02:49:21 CET 2017 PHP Warning: mysqli_query() expects parameter 1 to be mysqli, null given in /usr/local/ispconfig/server/lib/classes/db_mysql.inc.php on line 183
Thu Feb 16 02:49:21 CET 2017 PHP Warning: mysqli_query() expects parameter 1 to be mysqli, null given in /usr/local/ispconfig/server/lib/classes/db_mysql.inc.php on line 228
Thu Feb 16 02:49:43 CET 2017 16.02.2017-02:49 - WARNING - Falsche Anfrage / Wrong QuerySQL-Query = INSERT INTO sys_log (server_id,datalog_id,loglevel,tstamp,message) VALUES (1, 0, 1, UNIX_TIMESTAMP(), 'Falsche Anfrage / Wrong QuerySQL-Query = INSERT INTO sys_log (server_id,datalog_id,loglevel,tstamp,message) VALUES (1, 0, 1, UNIX_TIMESTAMP(), 'Falsche Anfrage / Wrong QuerySQL-Query = INSERT INTO sys_log (server_id,datalog_id,loglevel,tstamp,message) VALUES (1, 0, 1, UNIX_TIMESTAMP(), \'Falsche A[…]
Here the last line is the interesting one, being the recursive error message: the inability to log to the database is an error that is tried to be logged to the database, causing the same error again with a longer message etc. until something breaks and it lands in cron.log. In reality the message is much longer (megabytes). To demonstrate I attach a file containing its first 600 lines, folded to 100 characters per line with cat cron.log | fold -w 100 >cron.100cpl.log
.
I suppose the piece of code causing this is in server/lib/classes/db_mysql.inc.php
line 228-232 and it could be solved by replacing it with the following:
$this->_iQueryId = mysqli_query($this->_iConnId, $sQuery);
if (!$this->_iQueryId and !substr($sQuery, 0, 19) === "INSERT INTO sys_log") {
$sQuery = strlen($sQuery) > 100 ? substr($in,0,100) . " [...]" : $sQuery;
$this->_sqlerror('Falsche Anfrage / Wrong Query', 'SQL-Query = ' . $sQuery);
return false;
}
That solution works so far (no issues since, but will have to test more). It's not the cleanest solution admittedly … . Also this issue is related to (fixed) issue #3974 (closed) "Escape error" but not the same – this one is recursive, resulting in huge log messages right from the first one, instead of gradually building up message size second by second.