MDL-68874 dml: Add SQL stacktrace debugging mode

admin/settings/development.php

@@ -41,6 +41,13 @@ if ($hassiteconfig) { // speedup for non-admins, add all caps used on this page
     $temp->add(new admin_setting_configcheckbox('debugdisplay', new lang_string('debugdisplay', 'admin'), new lang_string('configdebugdisplay', 'admin'), ini_get_bool('display_errors')));
     $temp->add(new admin_setting_configcheckbox('perfdebug', new lang_string('perfdebug', 'admin'), new lang_string('configperfdebug', 'admin'), '7', '15', '7'));
     $temp->add(new admin_setting_configcheckbox('debugstringids', new lang_string('debugstringids', 'admin'), new lang_string('debugstringids_desc', 'admin'), 0));
+    $temp->add(new admin_setting_configselect('debugsqltrace',
+            new lang_string('debugsqltrace', 'admin'),
+            new lang_string('debugsqltrace_desc', 'admin'), 0, array(
+               0 => new lang_string('disabled', 'admin'),
+               1 => new lang_string('debugsqltrace1', 'admin'),
+               2 => new lang_string('debugsqltrace2', 'admin'),
+             100 => new lang_string('debugsqltrace100', 'admin'))));
     $temp->add(new admin_setting_configcheckbox('debugvalidators', new lang_string('debugvalidators', 'admin'), new lang_string('configdebugvalidators', 'admin'), 0));
     $temp->add(new admin_setting_configcheckbox('debugpageinfo', new lang_string('debugpageinfo', 'admin'), new lang_string('configdebugpageinfo', 'admin'), 0));
     $ADMIN->add('development', $temp);

lang/en/admin.php

@@ -462,6 +462,11 @@ $string['debugminimal'] = 'MINIMAL: Show only fatal errors';
 $string['debugnone'] = 'NONE: Do not show any errors or warnings';
 $string['debugnormal'] = 'NORMAL: Show errors, warnings and notices';
 $string['debugpageinfo'] = 'Show page information';
+$string['debugsqltrace'] = 'Show origin of SQL calls';
+$string['debugsqltrace1'] = 'Show only a single calling line';
+$string['debugsqltrace2'] = 'Show 2 lines of stack trace';
+$string['debugsqltrace100'] = 'Show full stack trace';
+$string['debugsqltrace_desc'] = 'If enabled adds either partial or full PHP stacktrace into the SQL as a comment';
 $string['debugstringids'] = 'Show origin of languages strings';
 $string['debugstringids_desc'] = 'If enabled, language string components and identifiers are displayed when ?strings=1 or &strings=1 is appended to the page URL.';
 $string['debugvalidators'] = 'Show validator links';

lib/dml/moodle_database.php

@@ -889,6 +889,9 @@ abstract class moodle_database {
         // convert table names
         $sql = $this->fix_table_names($sql);
 
+        // Optionally add debug trace to sql as a comment.
+        $sql = $this->add_sql_debugging($sql);
+
         // cast booleans to 1/0 int and detect forbidden objects
         foreach ($params as $key => $value) {
             $this->detect_objects($value);
@@ -1030,6 +1033,50 @@ abstract class moodle_database {
         }
     }
 
+    /**
+     * Add an SQL comment to trace all sql calls back to the calling php code
+     * @param string $sql Original sql
+     * @return string Instrumented sql
+     */
+    protected function add_sql_debugging(string $sql): string {
+        global $CFG;
+
+        if (!property_exists($CFG, 'debugsqltrace')) {
+            return $sql;
+        }
+
+        $level = $CFG->debugsqltrace;
+
+        if (empty($level)) {
+            return $sql;
+        }
+
+        $callers = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS);
+
+        // Ignore moodle_database internals.
+        $callers = array_filter($callers, function($caller) {
+            return empty($caller['class']) || $caller['class'] != 'moodle_database';
+        });
+
+        $callers = array_slice($callers, 0, $level);
+
+        $text = trim(format_backtrace($callers, true));
+
+        // Convert all linebreaks to SQL comments, optionally
+        // also eating any * formatting.
+        $text = preg_replace("/(^|\n)\*?\s*/", "\n-- ", $text);
+
+        // Convert all ? to 'unknown' in the sql coment so these don't get
+        // caught by fix_sql_params().
+        $text = str_replace('?', 'unknown', $text);
+
+        // Convert tokens like :test to ::test for the same reason.
+        $text = preg_replace('/(?<!:):[a-z][a-z0-9_]*/', ':\0', $text);
+
+        return $sql . $text;
+    }
+
+
     /**
      * Ensures that limit params are numeric and positive integers, to be passed to the database.
      * We explicitly treat null, '' and -1 as 0 in order to provide compatibility with how limit

lib/dml/tests/dml_test.php

@@ -438,6 +438,55 @@ class core_dml_testcase extends database_driver_testcase {
         $this->assertSame(array_values($params), array_values($inparams));
     }
 
+    /**
+     * Test the database debugging as SQL comment.
+     */
+    public function test_add_sql_debugging() {
+        global $CFG;
+        $DB = $this->tdb;
+
+        require_once($CFG->dirroot . '/lib/dml/tests/fixtures/test_dml_sql_debugging_fixture.php');
+        $fixture = new test_dml_sql_debugging_fixture($this);
+
+        $sql = "SELECT * FROM {users}";
+
+        $out = $fixture->four($sql);
+
+        $CFG->debugsqltrace = 0;
+        $this->assertEquals("SELECT * FROM {users}", $out);
+
+        $CFG->debugsqltrace = 1;
+        $out = $fixture->four($sql);
+        $expected = <<<EOD
+SELECT * FROM {users}
+-- line 65 of /lib/dml/tests/fixtures/test_dml_sql_debugging_fixture.php: call to ReflectionMethod->invoke()
+EOD;
+        $this->assertEquals($expected, $out);
+
+        $CFG->debugsqltrace = 2;
+        $out = $fixture->four($sql);
+        $expected = <<<EOD
+SELECT * FROM {users}
+-- line 65 of /lib/dml/tests/fixtures/test_dml_sql_debugging_fixture.php: call to ReflectionMethod->invoke()
+-- line 74 of /lib/dml/tests/fixtures/test_dml_sql_debugging_fixture.php: call to test_dml_sql_debugging_fixture->one()
+EOD;
+        $this->assertEquals($expected, $out);
+
+        $CFG->debugsqltrace = 5;
+        $out = $fixture->four($sql);
+        $expected = <<<EOD
+SELECT * FROM {users}
+-- line 65 of /lib/dml/tests/fixtures/test_dml_sql_debugging_fixture.php: call to ReflectionMethod->invoke()
+-- line 74 of /lib/dml/tests/fixtures/test_dml_sql_debugging_fixture.php: call to test_dml_sql_debugging_fixture->one()
+-- line 83 of /lib/dml/tests/fixtures/test_dml_sql_debugging_fixture.php: call to test_dml_sql_debugging_fixture->two()
+-- line 92 of /lib/dml/tests/fixtures/test_dml_sql_debugging_fixture.php: call to test_dml_sql_debugging_fixture->three()
+-- line 476 of /lib/dml/tests/dml_test.php: call to test_dml_sql_debugging_fixture->four()
+EOD;
+        $this->assertEquals($expected, $out);
+
+        $CFG->debugsqltrace = 0;
+    }
+
     public function test_strtok() {
         // Strtok was previously used by bound emulation, make sure it is not used any more.
         $DB = $this->tdb;

lib/dml/tests/fixtures/test_dml_sql_debugging_fixture.php

@@ -0,0 +1,95 @@
+<?php
+// This file is part of Moodle - http://moodle.org/
+//
+// Moodle is free software: you can redistribute it and/or modify
+// it under the terms of the GNU General Public License as published by
+// the Free Software Foundation, either version 3 of the License, or
+// (at your option) any later version.
+//
+// Moodle is distributed in the hope that it will be useful,
+// but WITHOUT ANY WARRANTY; without even the implied warranty of
+// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+// GNU General Public License for more details.
+//
+// You should have received a copy of the GNU General Public License
+// along with Moodle.  If not, see <http://www.gnu.org/licenses/>.
+
+/**
+ * Test SQL debugging fixture
+ *
+ * @package    core
+ * @category   dml
+ * @copyright  2020 Brendan Heywood <brendan@catalyst-au.net>
+ * @license    http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
+ */
+
+defined('MOODLE_INTERNAL') || die();
+
+/**
+ * Test SQL debugging fixture
+ *
+ * @package    core
+ * @category   dml
+ * @copyright  2020 Brendan Heywood <brendan@catalyst-au.net>
+ * @license    http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
+ */
+class test_dml_sql_debugging_fixture {
+    /** @var db handle */
+    private $db;
+
+    /**
+     * constructor
+     * @param testcase $testcase test object
+     */
+    public function __construct($testcase) {
+        $this->db = $testcase->getMockBuilder(\moodle_database::class)
+            ->getMockForAbstractClass();
+    }
+
+    /**
+     * Get db handle
+     * @return a db handle
+     */
+    public function get_mock() {
+        return $this->db;
+    }
+
+    /**
+     * Test caller in stacktrace
+     * @param string $sql original sql
+     * @return string sql with comments
+     */
+    public function one(string $sql) {
+        $method = new \ReflectionMethod($this->db, 'add_sql_debugging');
+        $method->setAccessible(true);
+        return $method->invoke($this->db, $sql);
+    }
+
+    /**
+     * Test caller in stacktrace
+     * @param string $sql original sql
+     * @return string sql with comments
+     */
+    public function two(string $sql) {
+        return $this->one($sql);
+    }
+
+    /**
+     * Test caller in stacktrace
+     * @param string $sql original sql
+     * @return string sql with comments
+     */
+    public function three(string $sql) {
+        return $this->two($sql);
+    }
+
+    /**
+     * Test caller in stacktrace
+     * @param string $sql original sql
+     * @return string sql with comments
+     */
+    public function four(string $sql) {
+        return $this->three($sql);
+    }
+
+}