From 4f1e2c1d271590b90c257a8eddbe3a7b2bf231be Mon Sep 17 00:00:00 2001 From: Matthieu Napoli <matthieu@mnapoli.fr> Date: Thu, 15 Jan 2015 12:17:57 +1300 Subject: [PATCH] Fixes #7017 (Infinite loop when logging to database at debug level) + tests The query log is momentarily disabled when the database log handler inserts in database --- core/Db.php | 22 ++++++++++++++++++++++ core/Log/Handler/DatabaseHandler.php | 19 ++++++++++++++----- tests/PHPUnit/Integration/Log/LogTest.php | 20 ++++++++++++++++++++ 3 files changed, 56 insertions(+), 5 deletions(-) diff --git a/core/Db.php b/core/Db.php index b781032d21..67618c8f58 100644 --- a/core/Db.php +++ b/core/Db.php @@ -35,6 +35,8 @@ class Db { private static $connection = null; + private static $logQueries = true; + /** * Returns the database connection and creates it if it hasn't been already. * @@ -710,7 +712,27 @@ class Db private static function logSql($functionName, $sql, $parameters = array()) { + if (self::$logQueries === false) { + return; + } + // NOTE: at the moment we don't log parameters in order to avoid sensitive information leaks Log::debug("Db::%s() executing SQL: %s", $functionName, $sql); } + + /** + * @param bool $enable + */ + public static function enableQueryLog($enable) + { + self::$logQueries = $enable; + } + + /** + * @return boolean + */ + public static function isQueryLogEnabled() + { + return self::$logQueries; + } } diff --git a/core/Log/Handler/DatabaseHandler.php b/core/Log/Handler/DatabaseHandler.php index 5981a7e919..1cdcd0f8b9 100644 --- a/core/Log/Handler/DatabaseHandler.php +++ b/core/Log/Handler/DatabaseHandler.php @@ -19,12 +19,21 @@ class DatabaseHandler extends AbstractProcessingHandler { protected function write(array $record) { - $sql = "INSERT INTO " . Common::prefixTable('logger_message') - . " (tag, timestamp, level, message)" - . " VALUES (?, ?, ?, ?)"; + $sql = sprintf( + 'INSERT INTO %s (tag, timestamp, level, message) VALUES (?, ?, ?, ?)', + Common::prefixTable('logger_message') + ); - $message = trim($record['formatted']); + $queryLog = Db::isQueryLogEnabled(); + Db::enableQueryLog(false); - Db::query($sql, array($record['extra']['class'], $record['datetime']->format('Y-m-d H:i:s'), $record['level_name'], $message)); + Db::query($sql, array( + $record['extra']['class'], + $record['datetime']->format('Y-m-d H:i:s'), + $record['level_name'], + trim($record['formatted']) + )); + + Db::enableQueryLog($queryLog); } } diff --git a/tests/PHPUnit/Integration/Log/LogTest.php b/tests/PHPUnit/Integration/Log/LogTest.php index 8fb10599d8..0b6516185e 100644 --- a/tests/PHPUnit/Integration/Log/LogTest.php +++ b/tests/PHPUnit/Integration/Log/LogTest.php @@ -164,6 +164,21 @@ class LogTest extends IntegrationTestCase $this->checkBackend($backend, self::TESTMESSAGE, $formatMessage = true, $tag); } + /** + * The database logs requests at DEBUG level, so we check that there is no recursive + * loop (logger insert in databases, which logs the query, ...) + * @link https://github.com/piwik/piwik/issues/7017 + */ + public function testNoInfiniteLoopWhenLoggingToDatabase() + { + Config::getInstance()->log['log_writers'] = array('database'); + Config::getInstance()->log['log_level'] = 'DEBUG'; + + Log::info(self::TESTMESSAGE); + + $this->checkBackend('database', self::TESTMESSAGE, $formatMessage = true, $tag = __CLASS__); + } + private function checkBackend($backend, $expectedMessage, $formatMessage = false, $tag = false) { if ($formatMessage) { @@ -178,6 +193,9 @@ class LogTest extends IntegrationTestCase $this->assertEquals($expectedMessage . "\n", $fileContents); } else if ($backend == 'database') { + $queryLog = Db::isQueryLogEnabled(); + Db::enableQueryLog(false); + $count = Db::fetchOne("SELECT COUNT(*) FROM " . Common::prefixTable('logger_message')); $this->assertEquals(1, $count); @@ -191,6 +209,8 @@ class LogTest extends IntegrationTestCase } else { $this->assertEquals($tag, $tagInDb); } + + Db::enableQueryLog($queryLog); } } -- GitLab