Log::findCaller fails to report the correct caller function with non-core drivers.

I want to support you doing your research. Here is for example a test for your fix, even it doesn't run yet. Do you have an idea by any change?

@mondrake
Good point. Its certainly worth trying out all database engines.

+++ b/core/lib/Drupal/Core/Database/Log.php
@@ -142,7 +143,18 @@ public function log(StatementInterface $statement, $args, $time) {
+    while (count($stack) > 2 && strpos((!empty($stack[0]['class']) ? $stack[0]['class'] : ''), $connection_namespace) === FALSE) {
+      array_shift($stack);
+    }
+    while (count($stack) > 2 && strpos((!empty($stack[0]['class']) ? $stack[0]['class'] : ''), $connection_namespace) === 0) {
+      array_shift($stack);
+    }

Can't you combine those two while statements into one using in_array(, , TRUE)?

1. +++ b/core/lib/Drupal/Core/Database/Log.php
   @@ -142,14 +143,27 @@ public function log(StatementInterface $statement, $args, $time) {
   +    $connection_namespace = $this->getConnectionNamespace();
   

   Should we statically cache this as a property on the class? Reflection isn't cheap - how frequently will findCaller be called? Does the namespace ever change?

2. +++ b/core/lib/Drupal/Core/Database/Log.php
   @@ -142,14 +143,27 @@ public function log(StatementInterface $statement, $args, $time) {
        for ($i = 0, $stack_count = count($stack); $i < $stack_count; ++$i) {
   

   In my opinion this whole chunk would be more readable if it used

   
   foreach ($stack as $ix => $entry)
   
   

   instead of for

   I realise its an existing issue, but if we're touching it, we should leave it in a happier place

3. +++ b/core/lib/Drupal/Core/Database/Log.php
   @@ -142,14 +143,27 @@ public function log(StatementInterface $statement, $args, $time) {
          if (empty($stack[$i]['class'])) {
            $stack[$i]['class'] = '';
          }
   

   There is some ugmo existing code here. Can we touch it up while we're here?

   $stack[$i] += ['class' => ''];
   

   would move three lines to one.

4. +++ b/core/lib/Drupal/Core/Database/Log.php
   @@ -142,14 +143,27 @@ public function log(StatementInterface $statement, $args, $time) {
   +      if (($is_driver_method === TRUE || $skipped_driver_methods ===  FALSE) && $i < $stack_count - 2) {
   

   why not

   if (($is_driver_method || !$skipped_driver_methods) ... 

5. +++ b/core/lib/Drupal/Core/Database/Log.php
   @@ -142,14 +143,27 @@ public function log(StatementInterface $statement, $args, $time) {
   +        if ($is_driver_method === TRUE) {
   

   why not

   if ($is_driver_method)
   

   this is definitely a boolean

6. +++ b/core/lib/Drupal/Core/Database/Log.php
   @@ -164,4 +178,24 @@ public function findCaller() {
   +    return debug_backtrace();
   

   nice work

7. +++ b/core/tests/Drupal/KernelTests/Core/Database/LoggingTest.php
   @@ -135,4 +137,180 @@ public function testGetLoggingWrongKey() {
   +      // Test that if the driver Connection is in the stack trace, the first
   +      // non-database entry is returned.
   +      [
   ...
   +      // Test that if the driver Connection is not in the stack trace, the very
   +      // last backtrace entry is still returned.
   

   nit: personally I prefer named test cases (use names in array keys instead of integers).

   The need for comments to describe the cases, illustrates that they would be useful.

Looking good to me, can you comment about the cleanup in #2088271: Undefined index: args in DatabaseLog->findCaller()?

The patch looks good, but I do have some remarks:

1. +++ b/core/lib/Drupal/Core/Database/Database.php
   @@ -503,7 +503,7 @@ public static function getConnectionInfoAsUrl($key = 'default') {
   -  protected static function getDatabaseDriverNamespace(array $connection_info) {
   +  public static function getDatabaseDriverNamespace(array $connection_info) {
   

   Changing this method from protected to public does warrend the creation of a change record.

2. +++ b/core/lib/Drupal/Core/Database/Log.php
   @@ -142,14 +150,26 @@ public function log(StatementInterface $statement, $args, $time) {
   +    $stack = $this->getDebugBacktrace();
   
   @@ -164,4 +184,31 @@ public function findCaller() {
   +  /**
   +   * Gets the debug backtrace.
   +   *
   +   * @return array[]
   +   *   The debug backtrace.
   +   */
   +  protected function getDebugBacktrace() {
   +    return debug_backtrace();
   +  }
   

   I think that moving the calling of debug_backtrace() to a separate method makes things only more complicated and unnecessary. If you do not agree, please explain why you think so.

3. +++ b/core/lib/Drupal/Core/Database/Log.php
   @@ -142,14 +150,26 @@ public function log(StatementInterface $statement, $args, $time) {
   +    $skipped_driver_methods = FALSE;
   

   Can you add some documentation about why/what this variable is for/what it does.

4. +++ b/core/lib/Drupal/Core/Database/Log.php
   @@ -142,14 +150,26 @@ public function log(StatementInterface $statement, $args, $time) {
   +      $is_driver_method = (strpos($stack[$i]['class'], $this->getConnectionNamespace()) === 0);
   

   Why do you compare the result of strpos() with === 0 and not with === FALSE?

5. +++ b/core/lib/Drupal/Core/Database/Log.php
   @@ -142,14 +150,26 @@ public function log(StatementInterface $statement, $args, $time) {
   +      if (($is_driver_method || !$skipped_driver_methods) && $i < $stack_count - 2) {
   

   Why do you add the part $i < $stack_count - 2? It is properly necessary, but I am missing the point. Sorry.

Just testing if a simpler solution would also work.

1. +++ b/core/lib/Drupal/Core/Database/Log.php
         // The function called is a method from the database driver if the class
         // name begins with the driver's namespace.
         $is_driver_method = (strpos($stack[$i]['class'], $this->getDriverNamespace()) === 0);
   
         // Skip all stack entries before and including methods called from the
         // database driver namespace. In case no database driver methods are
         // found, at least ensure the last two stack entries are left, so that
         // the very first function call in the stack can be returned as the
         // caller.
         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 [
             'file' => $stack[$i]['file'],
             'line' => $stack[$i]['line'],
             'function' => $stack[$i + 1]['function'],
             'class' => isset($stack[$i + 1]['class']) ? $stack[$i + 1]['class'] : NULL,
             'type' => isset($stack[$i + 1]['type']) ? $stack[$i + 1]['type'] : NULL,
             'args' => $stack[$i + 1]['args'],
           ];
         }
   

   Please do not see my following remarks as personal. Your work @mondrake on this and other issues is great. with that said:
   I get bad feeling of codesmell when I look at the above code. I find it diffecult to read and to really see want is happening.
   I am unable to test this code. Therefor am I asking you @mondrake if it is possible to change it to something like:

         if (strpos($stack[$i]['class'], $this->getDriverNamespace()) === FALSE  && !empty($stack[$i]['file'])) {
           $stack[$i] += ['file' => '?', 'line' => '?', 'args' => []];
           return [
             'file' => $stack[$i]['file'],
             'line' => $stack[$i]['line'],
             'function' => $stack[$i + 2]['function'],
             'class' => isset($stack[$i + 2]['class']) ? $stack[$i + 1]['class'] : NULL,
             'type' => isset($stack[$i + 2]['type']) ? $stack[$i + 1]['type'] : NULL,
             'args' => $stack[$i + 1]['args'],
           ];
         }
         if (strpos($stack[$i]['class'], __NAMESPACE__) === FALSE && strpos($stack[$i + 1]['function'], 'db_') === FALSE && !empty($stack[$i]['file'])) {
           $stack[$i] += ['file' => '?', 'line' => '?', 'args' => []];
           return [
             'file' => $stack[$i]['file'],
             'line' => $stack[$i]['line'],
             'function' => $stack[$i + 1]['function'],
             'class' => isset($stack[$i + 1]['class']) ? $stack[$i + 1]['class'] : NULL,
             'type' => isset($stack[$i + 1]['type']) ? $stack[$i + 1]['type'] : NULL,
             'args' => $stack[$i + 1]['args'],
           ];
         }
   

   If there is no other solution I will give your patch RTBC.

2. Maybe this is a stupid question, but does the this patch also fixes the problem if the database query is called from a "db_"-function for a 3rd party database driver?

+1 to RTBC.

The latest patch #53 was tested and added to Oracle Database Driver into installation instruction as a required one for proper work.

Related issue: #3107885: Fix Database\LoggingTest

@bohart: Thank you for testing the patch with your Oracle database driver.

The patch loks good to me. All my remarks are addressed.
The patch works for the Oacle database driver.
There are tests added.
The readability of the code from the findCaller method has been improved.
For me it is RTBC.

@mondrake: I think that something went wrong with your interdiff file.

The db_query parts have been removed.
It all looks good again.
Back to RTBC.

I'd be happy to test this on 8.8.x with SQL Server. I need to set up a travis-ci environment for 8.9.x and 9.0.x. #53 worked for me on 8.8.x another RTBC.

+++ b/core/lib/Drupal/Core/Database/Database.php
@@ -503,7 +503,7 @@ public static function getConnectionInfoAsUrl($key = 'default') {
-  protected static function getDatabaseDriverNamespace(array $connection_info) {
+  public static function getDatabaseDriverNamespace(array $connection_info) {

So this change is interesting. Here's the code of the method:

  protected static function getDatabaseDriverNamespace(array $connection_info) {
    if (isset($connection_info['namespace'])) {
      return $connection_info['namespace'];
    }
    // Fallback for Drupal 7 settings.php.
    return 'Drupal\\Core\\Database\\Driver\\' . $connection_info['driver'];
  }

I think in Drupal 9 this method is not even necessary. I've opened #3112476: Always set $info['namespace'] on database connection info. I'm not sure about making a method public that's not really necessary.

@mondrake i don't think this really increases compatibility or not. Also looking at the code we can do this without affecting the public API.

+++ b/core/lib/Drupal/Core/Database/Log.php
@@ -141,26 +150,65 @@ public function log(StatementInterface $statement, $args, $time) {
+      $connection_info = Database::getConnectionInfo($this->connectionKey);
+      if ($connection_info && isset($connection_info['default'])) {
+        $this->driverNamespace = Database::getDatabaseDriverNamespace($connection_info['default']);
+      }

This could be done this...

$connection = Database::getConnection('default', $this->connectionKey);
$this->driverNamespace = (new \ReflectionObject($connection))->getNamespaceName();

Note that exceptions will be thrown in the connection key and default target don't exist which imo is the correct behaviour because we can't log on a non-existent connection.

Well this is in-between runtime and debug code. It's only on during views ui query capture in core. Which is not the 99.999999% use of core db code.

The changes look good to me and it addresses the points made by @alexpott.
Back to RTBC.

#71 does not apply to 8.8.x. If someone could backport the patch, I can test on my sqlsrv github repo.

Committed 97bac4f and pushed to 9.0.x. Thanks!

If we want to fix this in Drupal 8.x then we need a new patch for 8.9.x

Works for sql server
#79 Works for SQL Server...I have reviewed the code and it meets my expectations and appears to be well formatted. I have installed the patch on my testing environment and testing failures now pass.

@Beakerboy: Thank you for reviewing the patch from this issue. Because of your short comment: "Works for sql server", I was wondering if you followed the reviewing guidelines set in https://www.drupal.org/patch/review? Let me point out that I am myself not always following those guidelines as good as should.

I think we need to do #3112476: Always set $info['namespace'] on database connection info first. If we can get the default namespace setting in $info back in 8.x then we don't need the additional protected methods for finding a driver namespace or mocking out debug_backtrace() - which leads to less API via inheritance to support. Which is a good thing - especially as our test coverage involves mocking out this API.

@alexpott, #3112476: Always set $info['namespace'] on database connection info has been RTBC for 3 weeks and it is holding up this issue. Do you have any comments?

@mondrake, Patch #71 needs to be rerolled

Rerolled patch for 9.1.x, please review.

Hi @mondrake, I have rerolled patch for 8.8.x, please review.

@mrinalini9 Is your patch any different than #79? They both fix the bug, so I don't see why one of them cannot be used.

Re-titling to make it clear this is about the 8.9 backport. What is the difference between the #95 and #79 patches?