- Patch #298669 by Crell, moshe et al: add query logging per connection.

includes/database/database.inc

@@ -139,6 +139,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);
@@ -262,6 +278,55 @@ protected function prepareQuery($query) {
     return $statements[$query];
   }
 
+  /**
+   * 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.
    *
@@ -672,6 +737,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.
    *
@@ -681,8 +815,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;
@@ -700,7 +840,9 @@ final public static function getConnection($key = 'default', $target = 'default'
     }
 
     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;
@@ -814,6 +956,8 @@ final public static function getConnectionInfo($key = 'default') {
    * @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;
@@ -843,12 +987,23 @@ final protected static function openConnection($key, $target) {
       $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
@@ -1050,7 +1205,20 @@ public function execute($args, $options) {
       }
     }
     $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;
   }
 
   /**

modules/simpletest/tests/database_test.test

@@ -123,7 +123,6 @@ class DatabaseConnectionTestCase extends DatabaseTestCase {
    * Test that connections return appropriate connection objects.
    */
   function testConnectionRouting() {
-
     // Clone the master credentials to a slave connection.
     // Note this will result in two independent connection objects that happen
     // to point to the same place.
@@ -156,7 +155,6 @@ class DatabaseConnectionTestCase extends DatabaseTestCase {
 
     $this->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,154 @@ 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.'));
+      }
+    }
+    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());
+    }
+  }
+}