[DPE-6488] Address slow mysqld start upon unit reboot (#615)

* Address slow mysqld start upon unit reboot

* Handle race conditions in snap restarts and update status executions + clean up error logging when recovering

* Fix failing unit test

* Run format

* Use simpler query for cluster metadata using mysqlsh

* Fix issue with get_cluster_metadata query when async setup used

* Fix failing unittest

* Address PR feedback

* Remove redundant check when executing manual rejoin

* Bump libpatch of the mysql charm lib

* Increase number of log lines retrieved in assertion to account for error traces

* Address edge case in rollback test where snap refresh was unnecessary

* Use status log to determine successful rollback instead of debug logs

Author: shayancanonical

lib/charms/mysql/v0/async_replication.py

@@ -730,7 +730,7 @@ def _on_consumer_relation_created(self, event):
         """Handle the async_replica relation being created on the leader unit."""
         if not self._charm.unit.is_leader():
             return
-        if not self._charm.unit_initialized and not self.returning_cluster:
+        if not self._charm.unit_initialized() and not self.returning_cluster:
             # avoid running too early for non returning clusters
             self._charm.unit.status = BlockedStatus(
                 "Wait until unit is initialized before running create-replication on offer side"

lib/charms/mysql/v0/mysql.py

@@ -133,7 +133,7 @@ def wait_until_mysql_connection(self) -> None:
 # Increment this major API version when introducing breaking changes
 LIBAPI = 0
 
-LIBPATCH = 84
+LIBPATCH = 85
 
 UNIT_TEARDOWN_LOCKNAME = "unit-teardown"
 UNIT_ADD_LOCKNAME = "unit-add"
@@ -418,6 +418,10 @@ class MySQLPluginInstallError(Error):
     """Exception raised when there is an issue installing a MySQL plugin."""
 
 
+class MySQLClusterMetadataExistsError(Error):
+    """Exception raised when there is an issue checking if cluster metadata exists."""
+
+
 @dataclasses.dataclass
 class RouterUser:
     """MySQL Router user."""
@@ -618,8 +622,15 @@ def cluster_initialized(self) -> bool:
             return False
 
         for unit in self.app_units:
-            if self._mysql.cluster_metadata_exists(self.get_unit_address(unit)):
-                return True
+            try:
+                if unit != self.unit and self._mysql.cluster_metadata_exists(
+                    self.get_unit_address(unit)
+                ):
+                    return True
+                elif self._mysql.cluster_metadata_exists():
+                    return True
+            except MySQLClusterMetadataExistsError:
+                pass
 
         return False
 
@@ -660,11 +671,6 @@ def unit_configured(self) -> bool:
             self.get_unit_address(self.unit), self.unit_label
         )
 
-    @property
-    def unit_initialized(self) -> bool:
-        """Check if the unit is added to the cluster."""
-        return self._mysql.cluster_metadata_exists(self.get_unit_address(self.unit))
-
     @property
     def app_peer_data(self) -> Union[ops.RelationDataContent, dict]:
         """Application peer relation data object."""
@@ -743,6 +749,15 @@ def removing_unit(self) -> bool:
         """Check if the unit is being removed."""
         return self.unit_peer_data.get("unit-status") == "removing"
 
+    def unit_initialized(self, raise_exceptions: bool = False) -> bool:
+        """Check if the unit is added to the cluster."""
+        try:
+            return self._mysql.cluster_metadata_exists()
+        except MySQLClusterMetadataExistsError:
+            if raise_exceptions:
+                raise
+            return False
+
     def peer_relation_data(self, scope: Scopes) -> DataPeerData:
         """Returns the peer relation data per scope."""
         if scope == APP_SCOPE:
@@ -1671,35 +1686,62 @@ def is_cluster_in_cluster_set(self, cluster_name: str) -> Optional[bool]:
 
         return cluster_name in cs_status["clusters"]
 
-    def cluster_metadata_exists(self, from_instance: str) -> bool:
-        """Check if this cluster metadata exists on database."""
-        check_cluster_metadata_commands = (
-            "result = session.run_sql(\"SHOW DATABASES LIKE 'mysql_innodb_cluster_metadata'\")",
-            "content = result.fetch_all()",
-            "if content:",
-            (
-                '  result = session.run_sql("SELECT cluster_name FROM mysql_innodb_cluster_metadata'
-                f".clusters where cluster_name = '{self.cluster_name}';\")"
-            ),
-            "  print(bool(result.fetch_one()))",
-            "else:",
-            "  print(False)",
+    def cluster_metadata_exists(self, from_instance: Optional[str] = None) -> bool:
+        """Check if this cluster metadata exists on database.
+
+        Use mysqlsh when querying clusters from remote instances. However, use
+        mysqlcli when querying locally since this method can be called before
+        the cluster is initialized (before serverconfig and root users are set up
+        correctly)
+        """
+        get_clusters_query = (
+            "SELECT cluster_name "
+            "FROM mysql_innodb_cluster_metadata.clusters "
+            "WHERE EXISTS ("
+            "SELECT * "
+            "FROM information_schema.schemata "
+            "WHERE schema_name = 'mysql_innodb_cluster_metadata'"
+            ")"
         )
 
+        if from_instance:
+            check_cluster_metadata_commands = (
+                f'cursor = session.run_sql("{get_clusters_query}")',
+                "print(cursor.fetch_all())",
+            )
+
+            try:
+                output = self._run_mysqlsh_script(
+                    "\n".join(check_cluster_metadata_commands),
+                    user=self.server_config_user,
+                    password=self.server_config_password,
+                    host=self.instance_def(self.server_config_user, from_instance),
+                    timeout=60,
+                    exception_as_warning=True,
+                )
+            except MySQLClientError:
+                logger.warning(f"Failed to check if cluster metadata exists {from_instance=}")
+                raise MySQLClusterMetadataExistsError(
+                    f"Failed to check if cluster metadata exists {from_instance=}"
+                )
+
+            return self.cluster_name in output
+
         try:
-            output = self._run_mysqlsh_script(
-                "\n".join(check_cluster_metadata_commands),
-                user=self.server_config_user,
-                password=self.server_config_password,
-                host=self.instance_def(self.server_config_user, from_instance),
+            output = self._run_mysqlcli_script(
+                (get_clusters_query,),
+                user=ROOT_USERNAME,
+                password=self.root_password,
                 timeout=60,
                 exception_as_warning=True,
+                log_errors=False,
             )
         except MySQLClientError:
-            logger.warning(f"Failed to check if cluster metadata exists {from_instance=}")
-            return False
+            logger.warning("Failed to check if local cluster metadata exists")
+            raise MySQLClusterMetadataExistsError("Failed to check if cluster metadata exists")
 
-        return output.strip() == "True"
+        cluster_names = [entry[0].strip() for entry in output]
+        return self.cluster_name in cluster_names
 
     def rejoin_cluster(self, cluster_name) -> None:
         """Try to rejoin a cluster to the cluster set."""
@@ -1939,8 +1981,11 @@ def rescan_cluster(
 
     def is_instance_in_cluster(self, unit_label: str) -> bool:
         """Confirm if instance is in the cluster."""
-        if not self.cluster_metadata_exists(self.instance_address):
-            # early return if instance has no cluster metadata
+        try:
+            if not self.cluster_metadata_exists(self.instance_address):
+                # early return if instance has no cluster metadata
+                return False
+        except MySQLClusterMetadataExistsError:
             return False
 
         commands = (
@@ -3244,21 +3289,26 @@ def kill_client_sessions(self) -> None:
             logger.error("Failed to kill external sessions")
             raise MySQLKillSessionError
 
-    def check_mysqlsh_connection(self) -> bool:
-        """Checks if it is possible to connect to the server with mysqlsh."""
-        connect_commands = 'session.run_sql("SELECT 1")'
+    def check_mysqlcli_connection(self) -> bool:
+        """Checks if it is possible to connect to the server with mysqlcli."""
+        connect_commands = ("SELECT 1",)
 
         try:
-            self._run_mysqlsh_script(
+            self._run_mysqlcli_script(
                 connect_commands,
                 user=self.server_config_user,
                 password=self.server_config_password,
-                host=self.instance_def(self.server_config_user),
             )
             return True
         except MySQLClientError:
-            logger.error("Failed to connect to MySQL with mysqlsh")
-            return False
+            logger.warning("Failed to connect to MySQL with mysqlcli with server config user")
+
+            try:
+                self._run_mysqlcli_script(connect_commands)
+                return True
+            except MySQLClientError:
+                logger.error("Failed to connect to MySQL with mysqlcli with default root user")
+                return False
 
     def get_pid_of_port_3306(self) -> Optional[str]:
         """Retrieves the PID of the process that is bound to port 3306."""
@@ -3427,6 +3477,7 @@ def _run_mysqlcli_script(
         password: Optional[str] = None,
         timeout: Optional[int] = None,
         exception_as_warning: bool = False,
+        log_errors: bool = False,
     ) -> list:
         """Execute a MySQL CLI script.
 
@@ -3442,6 +3493,7 @@ def _run_mysqlcli_script(
             password: (optional) password to invoke the mysql cli script with
             timeout: (optional) time before the query should timeout
             exception_as_warning: (optional) whether the exception should be treated as warning
+            log_errors: (optional) whether errors in the output should be logged
         """
         raise NotImplementedError
 

lib/charms/mysql/v0/tls.py

@@ -91,7 +91,7 @@ def _on_set_tls_private_key(self, event: ActionEvent) -> None:
 
     def _on_tls_relation_joined(self, event) -> None:
         """Request certificate when TLS relation joined."""
-        if not self.charm.unit_initialized:
+        if not self.charm.unit_initialized():
             event.defer()
             return
         self._request_certificate(None)

src/charm.py

@@ -385,7 +385,7 @@ def _on_peer_relation_changed(self, event: RelationChangedEvent) -> None:
     def _on_database_storage_detaching(self, _) -> None:
         """Handle the database storage detaching event."""
         # Only executes if the unit was initialised
-        if not self.unit_initialized:
+        if not self.unit_initialized():
             return
 
         # No need to remove the instance from the cluster if it is not a member of the cluster
@@ -422,15 +422,15 @@ def _get_leader_unit() -> Optional[Unit]:
         # Inform other hooks of current status
         self.unit_peer_data["unit-status"] = "removing"
 
-    def _handle_non_online_instance_status(self, state) -> None:
+    def _handle_non_online_instance_status(self, state) -> bool:  # noqa: C901
         """Helper method to handle non-online instance statuses.
 
         Invoked from the update status event handler.
         """
         if state == "recovering":
             # server is in the process of becoming an active member
             logger.info("Instance is being recovered")
-            return
+            return True
 
         if state == "offline":
             # Group Replication is active but the member does not belong to any group
@@ -440,17 +440,28 @@ def _handle_non_online_instance_status(self, state) -> None:
             all_states.add("offline")
 
             if all_states == {"offline"} and self.unit.is_leader():
+                loopback_entry_exists = self.hostname_resolution.update_etc_hosts(None)
+                if loopback_entry_exists and not snap_service_operation(
+                    CHARMED_MYSQL_SNAP_NAME, CHARMED_MYSQLD_SERVICE, "restart"
+                ):
+                    self.unit.status = BlockedStatus(
+                        "Unable to restart mysqld before rebooting from complete outage"
+                    )
+                    return False
+
+                self._mysql.wait_until_mysql_connection()
+
                 # All instance are off or its a single unit cluster
                 # reboot cluster from outage from the leader unit
                 logger.info("Attempting reboot from complete outage.")
                 try:
                     # reboot from outage forcing it when it a single unit
                     self._mysql.reboot_from_complete_outage()
+                    return True
                 except MySQLRebootFromCompleteOutageError:
                     logger.error("Failed to reboot cluster from complete outage.")
                     self.unit.status = BlockedStatus("failed to recover cluster.")
-                finally:
-                    return
+                    return False
 
             if self._mysql.is_cluster_auto_rejoin_ongoing():
                 logger.info("Cluster auto-rejoin attempts are still ongoing.")
@@ -466,8 +477,12 @@ def _handle_non_online_instance_status(self, state) -> None:
                     # mysqld access not possible and daemon restart fails
                     # force reset necessary
                     self.unit.status = BlockedStatus("Unable to recover from an unreachable state")
+                    return False
             except SnapServiceOperationError as e:
                 self.unit.status = BlockedStatus(e.message)
+                return False
+
+        return True
 
     def _execute_manual_rejoin(self) -> None:
         """Executes an instance manual rejoin.
@@ -509,7 +524,7 @@ def _on_update_status(self, _) -> None:  # noqa: C901
         if (
             self.unit_peer_data.get("member-state") == "waiting"
             and not self.unit_configured
-            and not self.unit_initialized
+            and not self.unit_initialized()
             and not self.unit.is_leader()
         ):
             # avoid changing status while in initialising
@@ -550,7 +565,8 @@ def _on_update_status(self, _) -> None:  # noqa: C901
             else MaintenanceStatus(state)
         )
 
-        self._handle_non_online_instance_status(state)
+        if not self._handle_non_online_instance_status(state):
+            return
 
         if self.unit.is_leader():
             try:
@@ -768,14 +784,19 @@ def _can_start(self, event: StartEvent) -> bool:
             return True
 
         # Safeguard if receiving on start after unit initialization
-        # with retries to allow time for mysqld startup
-        for _ in range(6):
-            if self.unit_initialized:
-                logger.debug("Delegate status update for start handler on initialized unit.")
-                self._on_update_status(None)
-                return False
-            logger.debug("mysqld not started yet. Retrying check")
-            sleep(5)
+        # with retries to allow for mysqld startup
+        try:
+            for attempt in Retrying(stop=stop_after_attempt(6), wait=wait_fixed(5)):
+                with attempt:
+                    if self.unit_initialized(raise_exceptions=True):
+                        logger.debug(
+                            "Delegate status update for start handler on initialized unit."
+                        )
+                        self._on_update_status(None)
+                        return False
+        except RetryError:
+            event.defer()
+            return False
 
         return True
 
@@ -786,7 +807,7 @@ def _is_unit_waiting_to_join_cluster(self) -> bool:
         return (
             self.unit_peer_data.get("member-state") == "waiting"
             and self.unit_configured
-            and not self.unit_initialized
+            and not self.unit_initialized()
             and self.cluster_initialized
         )
 
@@ -897,7 +918,7 @@ def recover_unit_after_restart(self) -> None:
 
     def _restart(self, _: EventBase) -> None:
         """Restart the service."""
-        if not self.unit_initialized:
+        if not self.unit_initialized():
             logger.debug("Restarting standalone mysqld")
             self._mysql.restart_mysqld()
             return

src/flush_mysql_logs.py

@@ -44,7 +44,7 @@ def _flush_mysql_logs(self, _) -> None:
         """Flush the specified (via LOGS_TYPE env var) mysql logs."""
         if (
             self.charm.peers is None
-            or not self.charm.unit_initialized
+            or not self.charm.unit_initialized()
             or not self.charm.upgrade.idle
             or not self.charm._mysql.is_mysqld_running()
         ):