DPE-7726: Extra Debug (Remove?)

Author: taurus-forever

src/charm.py

@@ -219,7 +219,7 @@ def is_compatible(
     def refresh_snap(
         self, *, snap_name: str, snap_revision: str, refresh: charm_refresh.Machines
     ) -> None:
-        # Update the configuration.
+        logger.debug("Update Patroni config on snap refresh")
         self._charm.set_unit_status(MaintenanceStatus("updating configuration"), refresh=refresh)
         self._charm.update_config(refresh=refresh)
         self._charm.updated_synchronous_node_count()
@@ -407,6 +407,7 @@ def set_unit_status(
                 json.dumps(refresh_status.message)
             )
             return
+        logger.debug(f"Set unit status: {status}")
         self.unit.status = status
 
     def _reconcile_refresh_status(self, _=None):
@@ -444,8 +445,8 @@ def _reconcile_refresh_status(self, _=None):
 
     def _on_databases_change(self, _):
         """Handle databases change event."""
+        logger.debug("Update Patroni config on databases changed")
         self.update_config()
-        logger.debug("databases changed")
         timestamp = datetime.now()
         self.unit_peer_data.update({"pg_hba_needs_update_timestamp": str(timestamp)})
         logger.debug(f"authorisation rules changed at {timestamp}")
@@ -617,9 +618,12 @@ def primary_endpoint(self) -> str | None:
             return None
         try:
             primary = self._patroni.get_primary()
+            logger.debug(f"primary_endpoint: got primary '{primary}'")
             if primary is None and (standby_leader := self._patroni.get_standby_leader()):
+                logger.debug(f"Using standby_leader {standby_leader} as primary")
                 primary = standby_leader
             primary_endpoint = self._patroni.get_member_ip(primary) if primary else None
+            logger.debug(f"primary_endpoint: got primary endpoint '{primary_endpoint}'")
             # Force a retry if there is no primary or the member that was
             # returned is not in the list of the current cluster members
             # (like when the cluster was not updated yet after a failed switchover).
@@ -709,8 +713,9 @@ def _on_peer_relation_departed(self, event: RelationDepartedEvent) -> None:
                 event.defer()
                 return
 
-            # Update the list of the current members.
+            logger.debug("Update the list of the current members")
             self._remove_from_members_ips(member_ip)
+            logger.debug("Update Patroni config on peer relation departure")
             self.update_config()
 
             if self.primary_endpoint:
@@ -863,6 +868,8 @@ def has_raft_keys(self):
     def _peer_relation_changed_checks(self, event: HookEvent) -> bool:
         """Split of to reduce complexity."""
         # Prevents the cluster to be reconfigured before it's bootstrapped in the leader.
+        logger.debug(f"Calling on_peer_relation_changed, event: '{event}'")
+
         if not self.is_cluster_initialised:
             logger.debug("Early exit on_peer_relation_changed: cluster not initialized")
             return False
@@ -891,7 +898,7 @@ def _on_peer_relation_changed(self, event: HookEvent):
 
         # Update the list of the cluster members in the replicas to make them know each other.
         try:
-            # Update the members of the cluster in the Patroni configuration on this unit.
+            logger.debug("Update the members of the cluster in Patroni on this unit")
             self.update_config()
         except RetryError:
             self.set_unit_status(BlockedStatus("failed to update cluster members on member"))
@@ -1069,12 +1076,14 @@ def add_cluster_member(self, member: str) -> None:
             NotReadyError if either the new member or the current members are not ready.
         """
         unit = self.model.get_unit(label2name(member))
+        logger.debug(f"add_cluster_member: adding unit {unit} to the cluster")
         if member_ip := self._get_unit_ip(unit):
             if not self._patroni.are_all_members_ready():
                 logger.info("not all members are ready")
                 raise NotReadyError("not all members are ready")
 
-            # Add the member to the list that should be updated in each other member.
+            # It should be updated in each other member.
+            logger.debug(f"Add member {member_ip} to the members_ips list")
             self._add_to_members_ips(member_ip)
 
             # Update Patroni configuration file.
@@ -1190,6 +1199,7 @@ def _units_ips(self) -> set[str]:
             for unit in self._peers.units:
                 if ip := self._get_unit_ip(unit):
                     addresses.add(ip)
+        logger.debug(f"_units_ips addresses: {addresses}")
         return addresses
 
     @property
@@ -1327,7 +1337,7 @@ def _on_install(self, event: InstallEvent) -> None:
             self._reboot_on_detached_storage(event)
             return
 
-        self.set_unit_status(MaintenanceStatus("installing PostgreSQL"))
+        self.set_unit_status(MaintenanceStatus("downloading & installing PostgreSQL"))
 
         # Install the charmed PostgreSQL snap.
         try:
@@ -1399,6 +1409,7 @@ def _on_leader_elected(self, event: LeaderElectedEvent) -> None:  # noqa: C901
         if not self.get_secret(APP_SCOPE, "internal-ca"):
             self.tls.generate_internal_peer_ca()
             self.tls.generate_internal_peer_cert()
+        logger.debug("Update Patroni config on leader elected")
         self.update_config()
 
         # Don't update connection endpoints in the first time this event run for
@@ -1443,10 +1454,10 @@ def _on_config_changed(self, event) -> None:  # noqa: C901
 
         try:
             self._validate_config_options()
-            # update config on every run
+            logger.debug("Update Patroni config on config changed")
             self.update_config()
-        except psycopg2.OperationalError:
-            logger.debug("Defer on_config_changed: Cannot connect to database")
+        except psycopg2.OperationalError as e:
+            logger.debug(f"Defer on_config_changed: Cannot connect to database ({e})")
             event.defer()
             return
         except ValueError as e:
@@ -1503,14 +1514,17 @@ def enable_disable_extensions(self, database: str | None = None) -> None:
                 continue
             extension = PLUGIN_OVERRIDES.get(extension, extension)
             if self._check_extension_dependencies(extension, enable):
+                logger.debug(f"Early exit: {extension} has broken dependencies")
                 self.set_unit_status(BlockedStatus(EXTENSIONS_DEPENDENCY_MESSAGE))
                 return
             extensions[extension] = enable
         if self.is_blocked and self.unit.status.message == EXTENSIONS_DEPENDENCY_MESSAGE:
+            logger.debug("Marking unit as Active")
             self.set_unit_status(ActiveStatus())
             original_status = self.unit.status
         self.set_unit_status(WaitingStatus("Updating extensions"))
         try:
+            logger.debug("Enabling/disabling PostgreSQL extensions...")
             self.postgresql.enable_disable_extensions(extensions, database)
         except psycopg2.errors.DependentObjectsStillExist as e:
             logger.error(
@@ -1522,8 +1536,10 @@ def enable_disable_extensions(self, database: str | None = None) -> None:
         except PostgreSQLEnableDisableExtensionError as e:
             logger.exception("failed to change plugins: %s", str(e))
         if original_status.message == EXTENSION_OBJECT_MESSAGE:
+            logger.debug("Marking unit as Active and finish with extensions")
             self.set_unit_status(ActiveStatus())
             return
+        logger.debug(f"Restoring original unit status to {original_status}")
         self.set_unit_status(original_status)
 
     def _check_extension_dependencies(self, extension: str, enable: bool) -> bool:
@@ -1604,16 +1620,19 @@ def _on_start(self, event: StartEvent) -> None:
         # Only the leader can bootstrap the cluster.
         # On replicas, only prepare for starting the instance later.
         if not self.unit.is_leader():
+            logger.debug("Prepare for starting replica instance later")
             self._start_replica(event)
             self._restart_services_after_reboot()
             return
 
-        # Bootstrap the cluster in the leader unit.
-        self._start_primary(event)
-        self._restart_services_after_reboot()
+        logger.debug("Bootstrap the cluster in the leader unit")
+        self._start_primary(event)  # start Patroni
+        self._restart_services_after_reboot()  # start Patroni #2
 
     def _restart_services_after_reboot(self):
         """Restart the Patroni and pgBackRest after a reboot."""
+        logger.debug(f"_restart_services_after_reboot: self._unit_ip: {self._unit_ip}")
+        logger.debug(f"_restart_services_after_reboot: self.members_ips: {self.members_ips}")
         if self._unit_ip in self.members_ips:
             self._patroni.start_patroni()
             self.backup.start_stop_pgbackrest_service()
@@ -1702,6 +1721,8 @@ def _setup_ldap_sync(self, postgres_snap: snap.Snap | None = None) -> None:
         postgres_snap.restart(services=["ldap-sync"])
 
     def _setup_users(self) -> None:
+        """Create PostgreSQL users used/operated by charm."""
+        logger.debug("Setup PostgreSQL users")
         self.postgresql.create_predefined_instance_roles()
 
         # Create the default postgres database user that is needed for some
@@ -1710,14 +1731,14 @@ def _setup_users(self) -> None:
         # This event can be run on a replica if the machines are restarted.
         # For that case, check whether the postgres user already exits.
         users = self.postgresql.list_users()
-        # Create the backup user.
         if BACKUP_USER not in users:
+            logger.debug(f"Creating user {BACKUP_USER}")
             self.postgresql.create_user(
                 BACKUP_USER, new_password(), extra_user_roles=[ROLE_BACKUP]
             )
             self.postgresql.grant_database_privileges_to_user(BACKUP_USER, "postgres", ["connect"])
         if MONITORING_USER not in users:
-            # Create the monitoring user.
+            logger.debug(f"Creating user {MONITORING_USER}")
             self.postgresql.create_user(
                 MONITORING_USER,
                 self.get_secret(APP_SCOPE, MONITORING_PASSWORD_KEY),
@@ -1785,11 +1806,10 @@ def _start_primary(self, event: StartEvent) -> None:
         # Flag to know if triggers need to be removed after refresh
         self.app_peer_data["refresh_remove_trigger"] = "True"
 
-        # Clear unit data if this unit became a replica after a failover/switchover.
+        logger.debug("Clear unit data if this unit became a replica after a failover/switchover")
         self._update_relation_endpoints()
 
-        # Enable/disable PostgreSQL extensions if they were set before the cluster
-        # was fully initialised.
+        # if extensions were set before the cluster was fully initialised.
         self.enable_disable_extensions()
 
         logger.debug("Active workload time: %s", datetime.now())
@@ -1880,6 +1900,7 @@ def _update_admin_password(self, admin_secret_id: str) -> None:
 
         # Update and reload Patroni configuration in this unit to use the new password.
         # Other units Patroni configuration will be reloaded in the peer relation changed event.
+        logger.debug("Update Patroni config on admin password update")
         self.update_config()
 
     def _on_promote_to_primary(self, event: ActionEvent) -> None:
@@ -2015,6 +2036,7 @@ def _was_restore_successful(self) -> bool:
 
     def _can_run_on_update_status(self) -> bool:
         if not self.is_cluster_initialised:
+            logger.debug("Early exit on_update_status: cluster is not initialised")
             return False
 
         if self.has_raft_keys():
@@ -2076,6 +2098,7 @@ def _set_primary_status_message(self) -> None:
                 self.set_unit_status(
                     BlockedStatus(self.app_peer_data["s3-initialization-block-message"])
                 )
+                logger.debug("Early exit _set_primary_status_message: s3 is blocked")
                 return
             if self.unit.is_leader() and (
                 self.app_peer_data.get("logical-replication-validation") == "error"
@@ -2213,6 +2236,7 @@ def push_tls_files_to_workload(self) -> bool:
         )
 
         try:
+            logger.debug("Update Patroni config on push tls files to workload")
             return self.update_config()
         except Exception:
             logger.exception("TLS files failed to push. Error in config update")
@@ -2227,6 +2251,7 @@ def push_ca_file_into_workload(self, secret_name: str) -> bool:
             subprocess.check_call([UPDATE_CERTS_BIN_PATH])  # noqa: S603
 
         try:
+            logger.debug("Update Patroni config on push CA file into workload")
             return self.update_config()
         except Exception:
             logger.exception("CA file failed to push. Error in config update")
@@ -2240,6 +2265,7 @@ def clean_ca_file_from_workload(self, secret_name: str) -> bool:
         subprocess.check_call([UPDATE_CERTS_BIN_PATH])  # noqa: S603
 
         try:
+            logger.debug("Update Patroni config on clean CA file from workload")
             return self.update_config()
         except Exception:
             logger.exception("CA file failed to clean. Error in config update")
@@ -2319,6 +2345,7 @@ def update_config(
         refresh: charm_refresh.Machines | None = None,
     ) -> bool:
         """Updates Patroni config file based on the existence of the TLS files."""
+        logger.debug("Updating Patroni config")
         if refresh is None:
             refresh = self.refresh
 
@@ -2351,6 +2378,7 @@ def update_config(
             slots=replication_slots,
         )
         if no_peers:
+            logger.debug("Early exit update_config: no peers")
             return True
 
         if not self._is_workload_running:
@@ -2387,6 +2415,7 @@ def update_config(
             else max(4 * self.cpu_count, 100)
         )
 
+        logger.debug("Bulk update parameters controller by patroni")
         self._patroni.bulk_update_parameters_controller_by_patroni({
             "max_connections": max_connections,
             "max_prepared_transactions": self.config.memory_max_prepared_transactions,
@@ -2412,6 +2441,7 @@ def update_config(
 
         self.unit_peer_data.update({"user_hash": self.generate_user_hash})
         if self.unit.is_leader():
+            logger.debug(f"Updating user_hash in app databag on leader: {self.generate_user_hash}")
             self.app_peer_data.update({"user_hash": self.generate_user_hash})
         return True
 
@@ -2433,6 +2463,7 @@ def _validate_config_options(self) -> None:
         ):
             raise ValueError("request_date_style config option has an invalid value")
 
+        logger.debug("Checking timezone config options")
         if self.config.request_time_zone not in self.postgresql.get_postgresql_timezones():
             raise ValueError("request_time_zone config option has an invalid value")
 
@@ -2446,6 +2477,7 @@ def _validate_config_options(self) -> None:
 
     def _handle_postgresql_restart_need(self) -> None:
         """Handle PostgreSQL restart need based on the TLS configuration and configuration changes."""
+        logger.debug("Checking for PostgreSQL restart necessity")
         if self._can_connect_to_postgresql:
             restart_postgresql = self.is_tls_enabled != self.postgresql.is_tls_enabled(
                 check_current_host=True

src/cluster.py

@@ -213,7 +213,7 @@ def _dict_to_hba_string(_dict: dict[str, Any]) -> str:
 
     def bootstrap_cluster(self) -> bool:
         """Bootstrap a PostgreSQL cluster using Patroni."""
-        # Render the configuration files and start the cluster.
+        logger.debug("bootstrap_cluster: render the configuration files and start Patroni")
         self.configure_patroni_on_unit()
         return self.start_patroni()
 
@@ -603,7 +603,9 @@ def is_member_isolated(self) -> bool:
                         auth=self._patroni_auth,
                     )
                     logger.debug(
-                        "API is_member_isolated: %s (%s)", r["members"], r.elapsed.total_seconds()
+                        "API is_member_isolated: %s (%s)",
+                        r.json()["members"],
+                        r.elapsed.total_seconds(),
                     )
         except RetryError:
             # Return False if it was not possible to get the cluster info. Try again later.
@@ -850,7 +852,7 @@ def stop_patroni(self) -> bool:
 
     def switchover(self, candidate: str | None = None) -> None:
         """Trigger a switchover."""
-        # Try to trigger the switchover.
+        logger.debug("Triggering the switchover to {candidate}")
         for attempt in Retrying(stop=stop_after_delay(60), wait=wait_fixed(3)):
             with attempt:
                 current_primary = self.get_primary()
@@ -1009,6 +1011,7 @@ def remove_raft_member(self, member_ip: str) -> None:
 
             # Leader doesn't always trigger when changing it's own peer data.
             if self.charm.unit.is_leader():
+                logger.debug("Emitting peer_relation_changed on leader")
                 self.charm.on[PEER].relation_changed.emit(
                     unit=self.charm.unit,
                     app=self.charm.app,