diff --git a/includes/database/database.inc b/includes/database/database.inc index 4a1f89c..e08e198 100644 --- a/includes/database/database.inc +++ b/includes/database/database.inc @@ -146,6 +146,22 @@ abstract class DatabaseConnection extends PDO { */ public $lastStatement; + /** + * The database target this connection is for. + * + * We need this information for later auditing and logging. + * + * @var string + */ + protected $target = NULL; + + /** + * The current database logging object for this connection. + * + * @var DatabaseLog + */ + protected $logger = NULL; + function __construct($dsn, $username, $password, $driver_options = array()) { $driver_options[PDO::ATTR_ERRMODE] = PDO::ERRMODE_EXCEPTION; // Because the other methods don't seem to work right. parent::__construct($dsn, $username, $password, $driver_options); @@ -270,6 +286,55 @@ abstract class DatabaseConnection extends PDO { } /** + * Tell this connection object what its target value is. + * + * This is needed for logging and auditing. It's sloppy to do in the + * constructor because the constructor for child classes has a different + * signature. We therefore also ensure that this function is only ever + * called once. + * + * @param $target + * The target this connection is for. Set to NULL (default) to disable + * logging entirely. + */ + public function setTarget($target = NULL) { + if (!isset($this->target)) { + $this->target = $target; + } + } + + /** + * Returns the target this connection is associated with. + * + * @return + * The target string of this connection. + */ + public function getTarget() { + return $this->target; + } + + /** + * Associate a logging object with this connection. + * + * @param $logger + * The logging object we want to use. + */ + public function setLogger(DatabaseLog $logger) { + $this->logger = $logger; + } + + /** + * Get the current logging object for this connection. + * + * @return + * The current logging object for this connection. If there isn't one, + * NULL is returned. + */ + public function getLogger() { + return $this->logger; + } + + /** * Create the appropriate sequence name for a given table and serial field. * * This information is exposed to all database drivers, although it is only @@ -680,6 +745,75 @@ abstract class Database { static protected $activeKey = 'default'; /** + * An array of active query log objects. + * + * Every connection has one and only one logger object for all targets + * and logging keys. + * + * array( + * '$db_key' => DatabaseLog object. + * ); + * + * @var array + */ + static protected $logs = array(); + + /** + * Start logging a given logging key on the specified connection. + * + * @see DatabaseLog + * @param $logging_key + * The logging key to log. + * @param $key + * The database connection key for which we want to log. + * @return + * The query log object. Note that the log object does support richer + * methods than the few exposed through the Database class, so in some + * cases it may be desirable to access it directly. + */ + final public static function startLog($logging_key, $key = 'default') { + if (empty(self::$logs[$key])) { + self::$logs[$key] = new DatabaseLog($key); + + // Every target already active for this connection key needs to have + // the logging object associated with it. + if (!empty(self::$connections[$key])) { + foreach (self::$connections[$key] as $connection) { + $connection->setLogger(self::$logs[$key]); + } + } + } + + self::$logs[$key]->start($logging_key); + return self::$logs[$key]; + } + + /** + * Retrieve the queries logged on for given logging key. + * + * This method also ends logging for the specified key. To get the query log + * to date without ending the logger request the logging object by starting + * it again (which does nothing to an open log key) and call methods on it as + * desired. + * + * @see DatabaseLog + * @param $logging_key + * The logging key to log. + * @param $key + * The database connection key for which we want to log. + * @return + * The query log for the specified logging key and connection. + */ + final public static function getLog($logging_key, $key = 'default') { + if (empty(self::$logs[$key])) { + return NULL; + } + $queries = self::$logs[$key]->get($logging_key); + self::$logs[$key]->end($logging_key); + return $queries; + } + + /** * Gets the active connection object for the specified target. * * @return @@ -688,8 +822,14 @@ abstract class Database { final public static function getActiveConnection($target = 'default') { // This could just be a call to getConnection(), but that's an extra // method call for every single query. + if (!empty(self::$ignoreTargets[self::$activeKey][$target])) { + $target = 'default'; + } + if (!isset(self::$connections[self::$activeKey][$target])) { - self::openConnection(self::$activeKey, $target); + // If we're trying to open a target that doesn't exist, we need to know + // what the actual target we got was. + $target = self::openConnection(self::$activeKey, $target); } return isset(self::$connections[self::$activeKey][$target]) ? self::$connections[self::$activeKey][$target] : NULL; @@ -707,7 +847,9 @@ abstract class Database { } if (!isset(self::$connections[$key][$target])) { - self::openConnection($key, $target); + // If we're trying to open a target that doesn't exist, we need to know + // what the actual target we got was. + $target = self::openConnection(self::$activeKey, $target); } return isset(self::$connections[$key][$target]) ? self::$connections[$key][$target] : NULL; @@ -821,6 +963,8 @@ abstract class Database { * @param $target * The database target to open. If the specified target does not exist, * the "default" target will be used instead. + * @return + * The name of the target that was actually opened. */ final protected static function openConnection($key, $target) { global $db_prefix; @@ -850,12 +994,23 @@ abstract class Database { $driver_class = 'DatabaseConnection_' . $driver; require_once DRUPAL_ROOT . '/includes/database/' . $driver . '/database.inc'; self::$connections[$key][$target] = new $driver_class(self::$databaseInfo[$key][$target]); + self::$connections[$key][$target]->setTarget($target); + + // If we have any active logging objects for this connection key, we need + // to associate them with the connection we just opened. + if (!empty(self::$logs[$key])) { + self::$connections[$key][$target]->setLogger(self::$logs[$key]); + } // We need to pass around the simpletest database prefix in the request // and we put that in the user_agent header. if (preg_match("/^simpletest\d+$/", $_SERVER['HTTP_USER_AGENT'])) { $db_prefix = $_SERVER['HTTP_USER_AGENT']; } + + // Return the target that was actually opened in case the requested one + // didn't exist. + return $target; } catch (Exception $e) { // It is extremely rare that an exception will be generated here other @@ -1057,7 +1212,20 @@ class DatabaseStatement extends PDOStatement { } } $this->dbh->lastStatement = $this; - return parent::execute($args); + + $logger = $this->dbh->getLogger(); + if (!empty($logger)) { + $query_start = microtime(TRUE); + } + + $return = parent::execute($args); + + if (!empty($logger)) { + $query_end = microtime(TRUE); + $logger->log($this, $args, $query_end - $query_start); + } + + return $return; } /** diff --git a/includes/database/log.inc b/includes/database/log.inc new file mode 100644 index 0000000..0f88e10 --- /dev/null +++ b/includes/database/log.inc @@ -0,0 +1,159 @@ + '', args => array(), caller => '', target => '', time => 0), + * array(query => '', args => array(), caller => '', target => '', time => 0), + * ), + * ); + * + * @var array + */ + protected $queryLog = array(); + + /** + * The connection key for which this object is logging. + * + * @var string + */ + protected $connectionKey = 'default'; + + /** + * Constructor. + * + * @param $key + * The database connection key for which to enable logging. + */ + public function __construct($key = 'default') { + $this->connectionKey = $key; + } + + /** + * Begin logging queries to the specified connection and logging key. + * + * If the specified logging key is already running this method does nothing. + * + * @param $logging_key + * The identification key for this log request. By specifying different + * logging keys we are able to start and stop multiple logging runs + * simultaneously without them colliding. + */ + public function start($logging_key) { + if (empty($this->queryLog[$logging_key])) { + $this->clear($logging_key); + } + } + + /** + * Retrieve the query log for the specified logging key so far. + * + * @param $logging_key + * The logging key to fetch. + * @return + * An indexed array of all query records for this logging key. + */ + public function get($logging_key) { + return $this->queryLog[$logging_key]; + } + + /** + * Empty the query log for the specified logging key. + * + * This method does not stop logging, it simply clears the log. To stop + * logging, use the end() method. + * + * @param $logging_key + * The logging key to empty. + */ + public function clear($logging_key) { + $this->queryLog[$logging_key] = array(); + } + + /** + * Stop logging for the specified logging key. + * + * @param $logging_key + * The logging key to stop. + */ + public function end($logging_key) { + unset($this->queryLog[$logging_key]); + } + + /** + * Log a query to all active logging keys. + * + * @param $statement + * The prepared statement object to log. + * @param $args + * The arguments passed to the statement object. + * @param $time + * The time in milliseconds the query took to execute. + */ + public function log(DatabaseStatement $statement, $args, $time) { + foreach (array_keys($this->queryLog) as $key) { + $this->queryLog[$key][] = array( + 'query' => $statement->queryString, + 'args' => $args, + 'target' => $statement->dbh->getTarget(), + 'caller' => $this->findCaller(), + 'time' => $time, + ); + } + } + + /** + * Determine the routine that called this query. + * + * We define "the routine that called this query" as the first entry in + * the call stack that is not inside includes/database. That makes the + * climbing logic very simple, and handles the variable stack depth caused + * by the query builders. + * + * @link http://www.php.net/debug_backtrace + * @return + * This method returns a stack trace entry similar to that generated by + * debug_backtrace(). However, it flattens the trace entry and the trace + * entry before it so that we get the function and args of the function that + * called into the database system, not the function and args of the + * database call itself. + */ + public function findCaller() { + $stack = debug_backtrace(); + $stack_count = count($stack); + for ($i = 0; $i < $stack_count; ++$i) { + if (strpos($stack[$i]['file'], 'includes/database') === FALSE) { + return array( + 'file' => $stack[$i]['file'], + 'line' => $stack[$i]['line'], + 'function' => $stack[$i + 1]['function'], + 'args' => $stack[$i + 1]['args'], + ); + return $stack[$i]; + } + } + } +} diff --git a/modules/simpletest/tests/database_test.test b/modules/simpletest/tests/database_test.test index 857c252..328a49f 100644 --- a/modules/simpletest/tests/database_test.test +++ b/modules/simpletest/tests/database_test.test @@ -1,5 +1,5 @@ assertIdentical($db1, $db2, t('Both targets refer to the same connection.')); } - } /** @@ -351,7 +349,7 @@ class DatabaseInsertTestCase extends DatabaseTestCase { * Test that we can insert multiple records in one query object. */ function testMultiInsert() { - try { + try { $num_records_before = (int) db_query("SELECT COUNT(*) FROM {test}")->fetchField(); $query = db_insert('test'); @@ -379,7 +377,7 @@ class DatabaseInsertTestCase extends DatabaseTestCase { $this->assertIdentical($saved_age, '31', t('Can retrieve by name.')); $saved_age = db_query("SELECT age FROM {test} WHERE name = :name", array(':name' => 'Moe'))->fetchField(); $this->assertIdentical($saved_age, '32', t('Can retrieve by name.')); - } + } catch (Exception $e) { $this->assertTrue(FALSE, $e->getMessage()); } @@ -419,7 +417,7 @@ class DatabaseInsertTestCase extends DatabaseTestCase { $this->assertIdentical($saved_age, '31', t('Can retrieve by name.')); $saved_age = db_query("SELECT age FROM {test} WHERE name = :name", array(':name' => 'Moe'))->fetchField(); $this->assertIdentical($saved_age, '32', t('Can retrieve by name.')); - } + } catch (Exception $e) { $this->assertTrue(FALSE, $e->getMessage()); } @@ -453,7 +451,7 @@ class DatabaseInsertTestCase extends DatabaseTestCase { ->execute(); $this->assertIdentical($id, '5', t('Auto-increment ID returned successfully.')); - } + } catch (Exception $e) { $this->assertTrue(FALSE, $e->getMessage()); } @@ -1655,3 +1653,158 @@ class DatabaseRegressionTestCase extends DatabaseTestCase { $this->assertIdentical($name, $from_database, t("The database handles UTF-8 characters cleanly.")); } } + +/** + * Query logging tests. + */ +class DatabaseLoggingTestCase extends DatabaseTestCase { + + function getInfo() { + return array( + 'name' => t('Query logging'), + 'description' => t('Test the query logging facility.'), + 'group' => t('Database'), + ); + } + + /** + * Test that we can log the existence of a query. + */ + function testEnableLogging() { + try { + Database::startLog('testing'); + + db_query("SELECT name FROM {test} WHERE age > :age", array(':age' => 25))->fetchCol(); + db_query("SELECT age FROM {test} WHERE name = :name", array(':name' => 'Ringo'))->fetchCol(); + + $queries = Database::getLog('testing', 'default'); + + $this->assertEqual(count($queries), 2, t('Correct number of queries recorded.')); + + foreach ($queries as $query) { + $this->assertEqual($query['caller']['function'], __FUNCTION__, t('Correct function in query log.')); + } + + // For debugging, since SimpleTest offers no good debugging meachnism (irony!) + $this->pass(print_r($_SESSION['lg_debug'], 1)); + $_SESSION['lg_debug'] = array(); + } + catch(Exception $e) { + $this->fail($e->getMessage()); + } + } + + /** + * Test that we can run two logs in parallel. + */ + function testEnableMultiLogging() { + try { + Database::startLog('testing1'); + + db_query("SELECT name FROM {test} WHERE age > :age", array(':age' => 25))->fetchCol(); + + Database::startLog('testing2'); + + db_query("SELECT age FROM {test} WHERE name = :name", array(':name' => 'Ringo'))->fetchCol(); + + $queries1 = Database::getLog('testing1'); + $queries2 = Database::getLog('testing2'); + + $this->assertEqual(count($queries1), 2, t('Correct number of queries recorded for log 1.')); + $this->assertEqual(count($queries2), 1, t('Correct number of queries recorded for log 2.')); + } + catch(Exception $e) { + $this->fail($e->getMessage()); + } + } + + /** + * Test that we can log queries against multiple targets on the same connection. + */ + function testEnableTargetLogging() { + try { + // Clone the master credentials to a slave connection and to another fake + // connection. + $connection_info = Database::getConnectionInfo('default'); + Database::addConnectionInfo('default', 'slave', $connection_info['default']); + + Database::startLog('testing1'); + + db_query("SELECT name FROM {test} WHERE age > :age", array(':age' => 25))->fetchCol(); + + db_query("SELECT age FROM {test} WHERE name = :name", array(':name' => 'Ringo'), array('target' => 'slave'));//->fetchCol(); + + $queries1 = Database::getLog('testing1'); + + $this->assertEqual(count($queries1), 2, t('Recorded queries from all targets.')); + $this->assertEqual($queries1[0]['target'], 'default', t('First query used default target.')); + $this->assertEqual($queries1[1]['target'], 'slave', t('Second query used slave target.')); + } + catch(Exception $e) { + $this->fail($e->getMessage()); + } + } + + /** + * Test that logs to separate targets collapse to the same connection properly. + * + * This test is identical to the one above, except that it doesn't create + * a fake target so the query should fall back to running on the default + * target. + */ + function testEnableTargetLoggingNoTarget() { + try { + Database::startLog('testing1'); + + db_query("SELECT name FROM {test} WHERE age > :age", array(':age' => 25))->fetchCol(); + + // We use "fake" here as a target because any non-existent target will do. + // However, because all of the tests in this class share a single page + // request there is likely to be a target of "slave" from one of the other + // unit tests, so we use a target here that we know with absolute certainty + // does not exist. + db_query("SELECT age FROM {test} WHERE name = :name", array(':name' => 'Ringo'), array('target' => 'fake'))->fetchCol(); + + $queries1 = Database::getLog('testing1'); + + $this->assertEqual(count($queries1), 2, t('Recorded queries from all targets.')); + $this->assertEqual($queries1[0]['target'], 'default', t('First query used default target.')); + $this->assertEqual($queries1[1]['target'], 'default', t('Second query used default target as fallback.')); + } + catch(Exception $e) { + $this->fail($e->getMessage()); + } + } + + /** + * Test that we can log queries separately on different connections. + */ + function testEnableMultiConnectionLogging() { + try { + // Clone the master credentials to a fake connection. + // That both connections point to the same physical database is irrelevant. + $connection_info = Database::getConnectionInfo('default'); + Database::addConnectionInfo('test2', 'default', $connection_info['default']); + + Database::startLog('testing1'); + Database::startLog('testing1', 'test2'); + + db_query("SELECT name FROM {test} WHERE age > :age", array(':age' => 25))->fetchCol(); + + $old_key = db_set_active('test2'); + + db_query("SELECT age FROM {test} WHERE name = :name", array(':name' => 'Ringo'), array('target' => 'slave'))->fetchCol(); + + db_set_active($old_key); + + $queries1 = Database::getLog('testing1'); + $queries2 = Database::getLog('testing1', 'test2'); + + $this->assertEqual(count($queries1), 1, t('Correct number of queries recorded for first connection.')); + $this->assertEqual(count($queries2), 1, t('Correct number of queries recorded for second connection.')); + } + catch(Exception $e) { + $this->fail($e->getMessage()); + } + } +}