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

@@ -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
+   * Traversing the call stack from the very first call made during the
-   * the call stack that is not inside the includes/Drupal/Database directory
+   * request, we define "the routine that called this query" as the last entry
-   * and does have a file (which excludes call_user_func_array(), anonymous
+   * in the call stack that is not any method called from the namespace of the
-   * functions and similar). That makes the climbing logic very simple, and
+   * database driver, is not inside the Drupal\Core\Database namespace and does
-   * handles the variable stack depth caused by the query builders.
+   * 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();
+    $stack = $this->getDebugBacktrace();
-    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
+    // Starting from the very first entry processed during the request, find
-      // just easier to give it a default value than to try and integrate
+    // the first function call that can be identified as a call to a
-      // that into the if statement below.
+    // method/function in the database layer.
-      if (empty($stack[$i + 1]['class'])) {
+    for ($n = count($stack) - 1; $n >= 0; $n--) {
-        $stack[$i + 1]['class'] = '';
+      // 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'],
+          'class' => $stack[$i + 1]['class'] ?? NULL,
-          'type' => isset($stack[$i + 1]['type']) ? $stack[$i + 1]['type'] : NULL,
+          'type' => $stack[$i + 1]['type'] ?? NULL,
-          'args' => $stack[$i + 1]['args'],
+          '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();
+  }
+
 }

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',
+          ],
+        ],
+      ],
+    ];
+  }
+
 }