diff --git a/core/lib/Drupal/Core/Database/Log.php b/core/lib/Drupal/Core/Database/Log.php index bf142c2..13066f1 100644 --- a/core/lib/Drupal/Core/Database/Log.php +++ b/core/lib/Drupal/Core/Database/Log.php @@ -125,7 +125,8 @@ public function log(StatementInterface $statement, $args, $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 the includes/Drupal/Database directory, + * the call stack that is coming after any method called from the namespace + * of the database driver, is not inside the Drupal\Core\Database namespace, * does not begin with db_ and does have a file (which excludes * call_user_func_array(), anonymous functions and similar). That makes the * climbing logic very simple, and handles the variable stack depth caused by @@ -142,14 +143,27 @@ public function log(StatementInterface $statement, $args, $time) { * database call itself. */ public function findCaller() { - $stack = debug_backtrace(); + $stack = $this->getDebugBacktrace(); + $connection_namespace = $this->getConnectionNamespace(); + $skipped_driver_methods = FALSE; + for ($i = 0, $stack_count = count($stack); $i < $stack_count; ++$i) { // If the call was made from a function, 'class' will be empty. It's // just easier to give it a default value than to try and integrate - // that into the if statement below. + // that into the if statements below. if (empty($stack[$i]['class'])) { $stack[$i]['class'] = ''; } + // Skip all stack entries before and including methods called from the + // database driver namespace. In any case, ensure the last entry of the + // trace is returned. + $is_driver_method = (strpos($stack[$i]['class'], $connection_namespace) === 0); + if (($is_driver_method || !$skipped_driver_methods) && $i < $stack_count - 2) { + if ($is_driver_method) { + $skipped_driver_methods = TRUE; + } + continue; + } if (strpos($stack[$i]['class'], __NAMESPACE__) === FALSE && strpos($stack[$i + 1]['function'], 'db_') === FALSE && !empty($stack[$i]['file'])) { $stack[$i] += ['file' => '?', 'line' => '?', 'args' => []]; return [ @@ -164,4 +178,25 @@ public function findCaller() { } } + /** + * Gets the namespace of the database connection. + * + * @return string + * Namespace of the database connection. + */ + protected function getConnectionNamespace() { + $connection_class = get_class(Database::getConnection($this->connectionKey)); + return substr($connection_class, 0, strrpos($connection_class, '\\')); + } + + /** + * Gets the debug backtrace. + * + * @return array[] + * The debug backtrace. + */ + protected function getDebugBacktrace() { + return debug_backtrace(); + } + } diff --git a/core/tests/Drupal/KernelTests/Core/Database/LoggingTest.php b/core/tests/Drupal/KernelTests/Core/Database/LoggingTest.php index 0216d3e..b77756a 100644 --- a/core/tests/Drupal/KernelTests/Core/Database/LoggingTest.php +++ b/core/tests/Drupal/KernelTests/Core/Database/LoggingTest.php @@ -2,11 +2,13 @@ namespace Drupal\KernelTests\Core\Database; +use Drupal\Core\Database\Log; use Drupal\Core\Database\Database; /** * Tests the query logging facility. * + * @coversDefaultClass \Drupal\Core\Database\Log * @group Database */ class LoggingTest extends DatabaseTestBase { @@ -135,4 +137,180 @@ public function testGetLoggingWrongKey() { $this->assertEqual($result, [], 'The function getLog with a wrong key returns an empty array.'); } + /** + * Tests that a log called by a custom database driver returns proper caller. + * + * @param string $connection_namespace + * The connection namespace to be tested. + * @param array $expected_entry + * The expected stack entry. + * + * @covers ::findCaller + * + * @dataProvider providerContribDriverLog + */ + public function testContribDriverLog($connection_namespace, array $expected_entry) { + $stack = [ + [ + 'file' => '/var/www/core/lib/Drupal/Core/Database/Log.php', + 'line' => 118, + 'function' => 'findCaller', + 'class' => 'Drupal\\Core\\Database\\Log', + 'type' => '->', + 'args' => [], + ], + [ + 'file' => '/var/www/core/lib/Drupal/Core/Database/Statement.php', + 'line' => 63, + 'function' => 'log', + 'class' => 'Drupal\\Core\\Database\\Log', + 'type' => '->', + 'args' => [], + ], + [ + 'file' => '/var/www/vendor/doctrine/dbal/lib/Doctrine/DBAL/Statement.php', + 'line' => 168, + 'function' => 'execute', + 'class' => 'Drupal\\Core\\Database\\Statement', + 'type' => '->', + 'args' => [], + ], + [ + 'file' => '/var/www/modules/contrib/drudbal/drivers/lib/Drupal/Driver/Database/dbal/Connection.php', + 'line' => 183, + 'function' => 'execute', + 'class' => 'Doctrine\\DBAL\\Statement', + 'type' => '->', + 'args' => [], + ], + [ + 'file' => '/var/www/core/includes/database.inc', + 'line' => 61, + 'function' => 'query', + 'class' => 'Drupal\\Driver\\Database\\dbal\\Connection', + 'object' => NULL, + 'type' => '->', + 'args' => [], + ], + [ + 'file' => '/var/www/tests/Drupal/KernelTests/Core/Database/LoggingTest.php', + 'line' => 20, + 'function' => 'db_query', + 'args' => [], + ], + [ + 'class' => 'Drupal\\KernelTests\\Core\\Database\\LoggingTest', + 'function' => 'testEnableLogging', + 'type' => '->', + 'args' => [], + ], + [ + 'file' => '/var/www/vendor/phpunit/phpunit/src/Framework/TestCase.php', + 'line' => 908, + 'function' => 'invokeArgs', + 'class' => 'ReflectionMethod', + 'object' => NULL, + 'type' => '->', + 'args' => [], + ], + [ + 'file' => '/var/www/vendor/phpunit/phpunit/src/Framework/TestCase.php', + 'line' => 768, + 'function' => 'runTest', + 'class' => 'PHPUnit_Framework_TestCase', + 'object' => NULL, + 'type' => '->', + 'args' => [], + ], + [ + 'file' => '/var/www/vendor/phpunit/phpunit/src/Framework/TestResult.php', + 'line' => 612, + 'function' => 'runBare', + 'class' => 'PHPUnit_Framework_TestCase', + 'object' => NULL, + 'type' => '->', + 'args' => [], + ], + [ + 'file' => '/var/www/vendor/phpunit/phpunit/src/Framework/TestCase.php', + 'line' => 724, + 'function' => 'run', + 'class' => 'PHPUnit_Framework_TestResult', + 'object' => NULL, + 'type' => '->', + 'args' => [], + ], + [ + 'file' => '-', + 'line' => 52, + 'function' => 'run', + 'class' => 'PHPUnit_Framework_TestCase', + 'object' => NULL, + 'type' => '->', + 'args' => [], + ], + [ + 'file' => '-', + 'line' => 1574, + 'function' => '__phpunit_run_isolated_test', + 'args' => [], + ], + ]; + + $mock_builder = $this->getMockBuilder(Log::class); + $log = $mock_builder + ->setMethods(['getConnectionNamespace', 'getDebugBacktrace']) + ->getMock(); + $log->expects($this->once()) + ->method('getConnectionNamespace') + ->will($this->returnValue($connection_namespace)); + $log->expects($this->once()) + ->method('getDebugBacktrace') + ->will($this->returnValue($stack)); + + $result = $log->findCaller($stack); + $this->assertEquals($expected_entry, $result); + } + + /** + * Provides data for the testContribDriverLog test. + * + * @return array[] + * A associative array of simple arrays, each having the following elements: + * - the contrib driver Connection class namespace + * - the stack entry expected to be returned. + * + * @see ::testContribDriverLog() + */ + public function providerContribDriverLog() { + return [ + // Test that if the driver Connection is in the stack trace, the first + // non-database entry is returned. + 'contrib driver connection' => [ + 'Drupal\\Driver\\Database\\dbal', + [ + 'class' => 'Drupal\\KernelTests\\Core\\Database\\LoggingTest', + 'function' => 'testEnableLogging', + 'file' => '/var/www/tests/Drupal/KernelTests/Core/Database/LoggingTest.php', + 'line' => 20, + 'type' => '->', + 'args' => [], + ] + ], + // Test that if the driver Connection is not in the stack trace, the very + // last backtrace entry is still returned. + 'missing driver connection' => [ + 'Drupal\\Driver\\Database\\fake', + [ + 'file' => '-', + 'line' => 52, + 'function' => '__phpunit_run_isolated_test', + 'args' => [], + 'class' => null, + 'type' => null, + ] + ], + ]; + } + }