MDL-72077 dml: Readonly connection debugging

lib/dml/moodle_read_slave_trait.php

@@ -153,6 +153,7 @@ trait moodle_read_slave_trait {
         $this->pprefix = $prefix;
         $this->pdboptions = $dboptions;
 
+        $logconnection = false;
         if ($dboptions) {
             if (isset($dboptions['readonly'])) {
                 $this->wantreadslave = true;
@@ -180,9 +181,12 @@ trait moodle_read_slave_trait {
                 }
 
                 if (count($slaves) > 1) {
+                    // Don't shuffle for unit tests as order is important for them to pass.
+                    if (!PHPUNIT_TEST) {
                         // Randomise things a bit.
                         shuffle($slaves);
                     }
+                }
 
                 // Find first connectable readonly slave.
                 $rodb = [];
@@ -198,9 +202,17 @@ trait moodle_read_slave_trait {
                     try {
                         $this->raw_connect($rodb['dbhost'], $rodb['dbuser'], $rodb['dbpass'], $dbname, $prefix, $dboptions);
                         $this->dbhreadonly = $this->get_db_handle();
+                        if ($logconnection) {
+                            debugging(
+                                "Readonly db connection succeeded for host {$rodb['dbhost']}"
+                            );
+                        }
                         break;
-                    } catch (dml_connection_exception $e) { // phpcs:ignore
+                    } catch (dml_connection_exception $e) {
-                        // If readonly slave is not connectable we'll have to do without it.
+                        debugging(
+                            "Readonly db connection failed for host {$rodb['dbhost']}: {$e->debuginfo}"
+                        );
+                        $logconnection = true;
                     }
                 }
                 // ... lock_db queries always go to master.
@@ -212,7 +224,19 @@ trait moodle_read_slave_trait {
             }
         }
         if (!$this->dbhreadonly) {
+            try {
                 $this->set_dbhwrite();
+            } catch (dml_connection_exception $e) {
+                debugging(
+                    "Readwrite db connection failed for host {$this->pdbhost}: {$e->debuginfo}"
+                );
+                throw $e;
+            }
+            if ($logconnection) {
+                debugging(
+                    "Readwrite db connection succeeded for host {$this->pdbhost}"
+                );
+            }
         }
 
         return true;

lib/dml/tests/dml_mysqli_read_slave_test.php

@@ -40,7 +40,7 @@ require_once(__DIR__.'/fixtures/read_slave_moodle_database_mock_mysqli.php');
  * @license    http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
  * @covers     \mysqli_native_moodle_database
  */
-class dml_mysqli_read_slave_test extends \base_testcase {
+final class dml_mysqli_read_slave_test extends \database_driver_testcase {
     /**
      * Test readonly handle is not used for reading from special pg_*() call queries,
      * pg_try_advisory_lock and pg_advisory_unlock.
@@ -136,25 +136,102 @@ class dml_mysqli_read_slave_test extends \base_testcase {
      *
      * @return void
      */
-    public function test_real_readslave_connect_fail(): void {
+    public function test_real_readslave_connect_fail_host(): void {
         global $DB;
 
         if ($DB->get_dbfamily() != 'mysql') {
             $this->markTestSkipped('Not mysql');
         }
 
+        $invalidhost = 'host.that.is.not';
+
         // Open second connection.
         $cfg = $DB->export_dbconfig();
         if (!isset($cfg->dboptions)) {
             $cfg->dboptions = [];
         }
         $cfg->dboptions['readonly'] = [
-            'instance' => ['host.that.is.not'],
+            'instance' => [$invalidhost],
             'connecttimeout' => 1
         ];
 
-        $db2 = moodle_database::get_driver_instance($cfg->dbtype, $cfg->dblibrary);
+        $this->resetDebugging();
+        $db2 = \moodle_database::get_driver_instance($cfg->dbtype, $cfg->dblibrary);
         $db2->connect($cfg->dbhost, $cfg->dbuser, $cfg->dbpass, $cfg->dbname, $cfg->prefix, $cfg->dboptions);
         $this->assertTrue(count($db2->get_records('user')) > 0);
+
+        $debugging = array_map(function ($d) {
+            return $d->message;
+        }, $this->getDebuggingMessages());
+        $this->resetDebugging();
+        $this->assertEquals(2, count($debugging));
+        $this->assertMatchesRegularExpression(
+            sprintf(
+                '/%s%s/',
+                preg_quote("Readonly db connection failed for host {$invalidhost}:"),
+                '.* Name or service not known',
+                $cfg->dbname
+            ),
+            $debugging[0]
+        );
+        $this->assertEquals("Readwrite db connection succeeded for host {$cfg->dbhost}", $debugging[1]);
+    }
+
+    /**
+     * Test connection failure
+     *
+     * @return void
+     */
+    public function test_real_readslave_connect_fail_dbname(): void {
+        global $DB;
+
+        if ($DB->get_dbfamily() != 'mysql') {
+            $this->markTestSkipped("Not mysql");
+        }
+
+        $invaliddb = 'cannot-exist-really';
+
+        // Open second connection.
+        $cfg = $DB->export_dbconfig();
+        $cfg->dbname = $invaliddb;
+        if (!isset($cfg->dboptions)) {
+            $cfg->dboptions = [];
+        }
+        $cfg->dboptions['readonly'] = [
+            'instance' => [$cfg->dbhost],
+            'connecttimeout' => 1,
+        ];
+
+        $this->resetDebugging();
+        $db2 = \moodle_database::get_driver_instance($cfg->dbtype, $cfg->dblibrary);
+        try {
+            $db2->connect($cfg->dbhost, $cfg->dbuser, $cfg->dbpass, $cfg->dbname, $cfg->prefix, $cfg->dboptions);
+        } catch (\dml_connection_exception $e) {  // phpcs:ignore
+            // We cannot go with expectException() because it would skip the rest.
+        }
+
+        $debugging = array_map(function ($d) {
+            return $d->message;
+        }, $this->getDebuggingMessages());
+        $this->resetDebugging();
+        $this->assertEquals(2, count($debugging));
+        $this->assertMatchesRegularExpression(
+            sprintf(
+                '/%s%s/',
+                preg_quote("Readonly db connection failed for host {$cfg->dbhost}: "),
+                "Access denied for user .* to database '$invaliddb'",
+                $cfg->dbname
+            ),
+            $debugging[0]
+        );
+        $this->assertMatchesRegularExpression(
+            sprintf(
+                '/%s%s/',
+                preg_quote("Readwrite db connection failed for host {$cfg->dbhost}: "),
+                'Access denied for user .* '.preg_quote("to database '$invaliddb'"),
+                $cfg->dbname
+            ),
+            $debugging[1]
+        );
     }
 }

lib/dml/tests/dml_pgsql_read_slave_test.php

@@ -267,18 +267,37 @@ class dml_pgsql_read_slave_test extends \advanced_testcase {
             $this->markTestSkipped('Not postgres');
         }
 
+        $invalidhost = 'host.that.is.not';
+
         // Open second connection.
         $cfg = $DB->export_dbconfig();
         if (!isset($cfg->dboptions)) {
             $cfg->dboptions = array();
         }
         $cfg->dboptions['readonly'] = [
-            'instance' => ['host.that.is.not'],
+            'instance' => [$invalidhost],
             'connecttimeout' => 1
         ];
 
+        $this->resetDebugging();
         $db2 = moodle_database::get_driver_instance($cfg->dbtype, $cfg->dblibrary);
         $db2->connect($cfg->dbhost, $cfg->dbuser, $cfg->dbpass, $cfg->dbname, $cfg->prefix, $cfg->dboptions);
         $this->assertTrue(count($db2->get_records('user')) > 0);
+
+        $debugging = array_map(function ($d) {
+            return $d->message;
+        }, $this->getDebuggingMessages());
+        $this->resetDebugging();
+        $this->assertEquals(2, count($debugging));
+        $this->assertMatchesRegularExpression(
+            sprintf(
+                '/%s%s/',
+                preg_quote("Readonly db connection failed for host {$invalidhost}: "),
+                '.* Name or service not known',
+                $cfg->dbname
+            ),
+            $debugging[0]
+        );
+        $this->assertEquals("Readwrite db connection succeeded for host {$cfg->dbhost}", $debugging[1]);
     }
 }

lib/dml/tests/dml_read_slave_test.php

@@ -40,7 +40,7 @@ require_once(__DIR__.'/../../tests/fixtures/event_fixtures.php');
  * @license    http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
  * @covers     \moodle_read_slave_trait
  */
-class dml_read_slave_test extends \base_testcase {
+final class dml_read_slave_test extends \database_driver_testcase {
 
     /** @var float */
     static private $dbreadonlylatency = 0.8;
@@ -452,6 +452,8 @@ class dml_read_slave_test extends \base_testcase {
      * @return void
      */
     public function test_read_only_conn_fail(): void {
+        $this->resetDebugging();
+
         $DB = $this->new_db(false, 'test_ro_fail');
 
         $this->assertEquals(0, $DB->perf_get_reads_slave());
@@ -461,6 +463,15 @@ class dml_read_slave_test extends \base_testcase {
         $this->assertEquals('test_rw::test:test', $handle);
         $readsslave = $DB->perf_get_reads_slave();
         $this->assertEquals(0, $readsslave);
+
+        $debugging = array_map(function ($d) {
+            return $d->message;
+        }, $this->getDebuggingMessages());
+        $this->resetDebugging();
+        $this->assertEquals([
+            'Readonly db connection failed for host test_ro_fail: test_ro_fail',
+            'Readwrite db connection succeeded for host test_rw',
+        ], $debugging);
     }
 
     /**
@@ -470,6 +481,8 @@ class dml_read_slave_test extends \base_testcase {
      * @return void
      */
     public function test_read_only_conn_first_fail(): void {
+        $this->resetDebugging();
+
         $DB = $this->new_db(false, ['test_ro_fail', 'test_ro_ok']);
 
         $this->assertEquals(0, $DB->perf_get_reads_slave());
@@ -479,6 +492,15 @@ class dml_read_slave_test extends \base_testcase {
         $this->assertEquals('test_ro_ok::test:test', $handle);
         $readsslave = $DB->perf_get_reads_slave();
         $this->assertEquals(1, $readsslave);
+
+        $debugging = array_map(function ($d) {
+            return $d->message;
+        }, $this->getDebuggingMessages());
+        $this->resetDebugging();
+        $this->assertEquals([
+            'Readonly db connection failed for host test_ro_fail: test_ro_fail',
+            'Readonly db connection succeeded for host test_ro_ok',
+        ], $debugging);
     }
 
     /**