From 97bac4f16a514b0e4e7c02769508cbfd8368e679 Mon Sep 17 00:00:00 2001 From: Alex Pott Date: Fri, 21 Feb 2020 14:30:50 +0000 Subject: [PATCH] Issue #2867788 by mondrake, daffie, dawehner, alexpott, larowlan: Log::findCaller fails to report the correct caller function with non-core drivers --- core/lib/Drupal/Core/Database/Log.php | 79 +++++-- .../KernelTests/Core/Database/LoggingTest.php | 192 ++++++++++++++++++ 2 files changed, 254 insertions(+), 17 deletions(-) diff --git a/core/lib/Drupal/Core/Database/Log.php b/core/lib/Drupal/Core/Database/Log.php index 6eb4beda5f0..ce7780eb0ad 100644 --- a/core/lib/Drupal/Core/Database/Log.php +++ b/core/lib/Drupal/Core/Database/Log.php @@ -38,6 +38,13 @@ class Log { */ protected $connectionKey = 'default'; + /** + * The PHP namespace of the database driver that this object is logging. + * + * @var string + */ + protected $driverNamespace; + /** * Constructor. * @@ -124,11 +131,13 @@ class Log { /** * 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 - * 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 the query builders. + * Traversing the call stack from the very first call made during the + * request, we define "the routine that called this query" as the last entry + * in the call stack that is not any method called from the namespace of the + * database driver, is not inside the Drupal\Core\Database namespace 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 the query builders. * * See the @link http://php.net/debug_backtrace debug_backtrace() @endlink * function. @@ -141,26 +150,62 @@ class Log { * database call itself. */ public function findCaller() { - $stack = debug_backtrace(); - 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. - if (empty($stack[$i + 1]['class'])) { - $stack[$i + 1]['class'] = ''; + $stack = $this->getDebugBacktrace(); + + // Starting from the very first entry processed during the request, find + // the first function call that can be identified as a call to a + // method/function in the database layer. + for ($n = count($stack) - 1; $n >= 0; $n--) { + // If the call was made from a function, 'class' will be empty. We give + // it a default empty string value in that case. + $class = $stack[$n]['class'] ?? ''; + + if (strpos($class, __NAMESPACE__, 0) === 0 || strpos($class, $this->getDriverNamespace(), 0) === 0) { + break; } - if (strpos($stack[$i + 1]['class'], __NAMESPACE__) === FALSE && !empty($stack[$i]['file'])) { - $stack[$i] += ['file' => '?', 'line' => '?', 'args' => []]; + } + + // Return the previous function call whose stack entry has a 'file' key, + // that is, it is not a callback or a closure. + for ($i = $n; $i < count($stack); $i++) { + if (!empty($stack[$i]['file'])) { return [ 'file' => $stack[$i]['file'], 'line' => $stack[$i]['line'], 'function' => $stack[$i + 1]['function'], - 'class' => $stack[$i + 1]['class'], - 'type' => isset($stack[$i + 1]['type']) ? $stack[$i + 1]['type'] : NULL, - 'args' => $stack[$i + 1]['args'], + 'class' => $stack[$i + 1]['class'] ?? NULL, + 'type' => $stack[$i + 1]['type'] ?? NULL, + 'args' => $stack[$i + 1]['args'] ?? [], ]; } } } + /** + * Gets the namespace of the database driver. + * + * @return string|null + * Namespace of the database driver, or NULL if the connection is + * missing. + */ + protected function getDriverNamespace() { + if (!isset($this->driverNamespace)) { + $this->driverNamespace = (new \ReflectionObject(Database::getConnection('default', $this->connectionKey)))->getNamespaceName(); + } + return $this->driverNamespace; + } + + /** + * Gets the debug backtrace. + * + * Wraps the debug_backtrace function to allow mocking results in PHPUnit + * tests. + * + * @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 cb05877d08e..daa6a15a5cd 100644 --- a/core/tests/Drupal/KernelTests/Core/Database/LoggingTest.php +++ b/core/tests/Drupal/KernelTests/Core/Database/LoggingTest.php @@ -2,11 +2,14 @@ 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 +138,193 @@ class LoggingTest extends DatabaseTestBase { $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 $driver_namespace + * The driver namespace to be tested. + * @param string $stack + * A test debug_backtrace stack. + * @param array $expected_entry + * The expected stack entry. + * + * @covers ::findCaller + * + * @dataProvider providerContribDriverLog + */ + public function testContribDriverLog($driver_namespace, $stack, array $expected_entry) { + $mock_builder = $this->getMockBuilder(Log::class); + $log = $mock_builder + ->setMethods(['getDriverNamespace', 'getDebugBacktrace']) + ->getMock(); + $log->expects($this->any()) + ->method('getDriverNamespace') + ->will($this->returnValue($driver_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 PHP namespace + * - a test debug_backtrace stack + * - the stack entry expected to be returned. + * + * @see ::testContribDriverLog() + */ + public function providerContribDriverLog() { + $stack = [ + [ + 'file' => '/var/www/core/lib/Drupal/Core/Database/Log.php', + 'line' => 125, + 'function' => 'findCaller', + 'class' => 'Drupal\\Core\\Database\\Log', + 'object' => 'test', + 'type' => '->', + 'args' => [ + 0 => 'test', + ], + ], + [ + 'file' => '/var/www/libraries/drudbal/lib/Statement.php', + 'line' => 264, + 'function' => 'log', + 'class' => 'Drupal\\Core\\Database\\Log', + 'object' => 'test', + 'type' => '->', + 'args' => [ + 0 => 'test', + ], + ], + [ + 'file' => '/var/www/libraries/drudbal/lib/Connection.php', + 'line' => 213, + 'function' => 'execute', + 'class' => 'Drupal\\Driver\\Database\\dbal\\Statement', + 'object' => 'test', + 'type' => '->', + 'args' => [ + 0 => 'test', + ], + ], + [ + 'file' => '/var/www/core/tests/Drupal/KernelTests/Core/Database/LoggingTest.php', + 'line' => 23, + 'function' => 'query', + 'class' => 'Drupal\\Driver\\Database\\dbal\\Connection', + 'object' => 'test', + 'type' => '->', + 'args' => [ + 0 => 'test', + ], + ], + [ + 'file' => '/var/www/vendor/phpunit/phpunit/src/Framework/TestCase.php', + 'line' => 1154, + 'function' => 'testEnableLogging', + 'class' => 'Drupal\\KernelTests\\Core\\Database\\LoggingTest', + 'object' => 'test', + 'type' => '->', + 'args' => [ + 0 => 'test', + ], + ], + [ + 'file' => '/var/www/vendor/phpunit/phpunit/src/Framework/TestCase.php', + 'line' => 842, + 'function' => 'runTest', + 'class' => 'PHPUnit\\Framework\\TestCase', + 'object' => 'test', + 'type' => '->', + 'args' => [ + 0 => 'test', + ], + ], + [ + 'file' => '/var/www/vendor/phpunit/phpunit/src/Framework/TestResult.php', + 'line' => 693, + 'function' => 'runBare', + 'class' => 'PHPUnit\\Framework\\TestCase', + 'object' => 'test', + 'type' => '->', + 'args' => [ + 0 => 'test', + ], + ], + [ + 'file' => '/var/www/vendor/phpunit/phpunit/src/Framework/TestCase.php', + 'line' => 796, + 'function' => 'run', + 'class' => 'PHPUnit\\Framework\\TestResult', + 'object' => 'test', + 'type' => '->', + 'args' => [ + 0 => 'test', + ], + ], + [ + 'file' => 'Standard input code', + 'line' => 57, + 'function' => 'run', + 'class' => 'PHPUnit\\Framework\\TestCase', + 'object' => 'test', + 'type' => '->', + 'args' => [ + 0 => 'test', + ], + ], + [ + 'file' => 'Standard input code', + 'line' => 111, + 'function' => '__phpunit_run_isolated_test', + 'args' => [ + 0 => 'test', + ], + ], + ]; + + return [ + // Test that if the driver namespace is in the stack trace, the first + // non-database entry is returned. + 'contrib driver namespace' => [ + 'Drupal\\Driver\\Database\\dbal', + $stack, + [ + 'class' => 'Drupal\\KernelTests\\Core\\Database\\LoggingTest', + 'function' => 'testEnableLogging', + 'file' => '/var/www/core/tests/Drupal/KernelTests/Core/Database/LoggingTest.php', + 'line' => 23, + 'type' => '->', + 'args' => [ + 0 => 'test', + ], + ], + ], + // Extreme case, should not happen at normal runtime - if the driver + // namespace is not in the stack trace, the first entry to a method + // in core database namespace is returned. + 'missing driver namespace' => [ + 'Drupal\\Driver\\Database\\fake', + $stack, + [ + 'class' => 'Drupal\\Driver\\Database\\dbal\\Statement', + 'function' => 'execute', + 'file' => '/var/www/libraries/drudbal/lib/Statement.php', + 'line' => 264, + 'type' => '->', + 'args' => [ + 0 => 'test', + ], + ], + ], + ]; + } + }