Increase debug verbosity (especially for REST API requests)

* Also use common logger everywhere.

(cherry picked from commit 0d332d9c22c6acb96a165576b9488c7fa31734f6)

Author: taurus-forever

lib/charms/postgresql_k8s/v1/postgresql.py

@@ -255,8 +255,10 @@ def _connect_to_database(
              psycopg2 connection object.
         """
         host = database_host if database_host is not None else self.primary_host
+        dbname = database if database else self.database
+        logger.debug(f"New DB connection: dbname='{dbname}' user='{self.user}' host='{host}' connect_timeout=1")
         connection = psycopg2.connect(
-            f"dbname='{database if database else self.database}' user='{self.user}' host='{host}'"
+            f"dbname='{dbname}' user='{self.user}' host='{host}'"
             f"password='{self.password}' connect_timeout=1"
         )
         connection.autocommit = True

src/charm.py

@@ -178,7 +178,7 @@ def unit_number(unit_name: str):
         # Lowest unit number is last to refresh
         last_unit_to_refresh = sorted(all_units, key=unit_number)[0].replace("/", "-")
         if self._charm._patroni.get_primary() == last_unit_to_refresh:
-            logging.info(
+            logger.info(
                 f"Unit {last_unit_to_refresh} was already primary during pre-refresh check"
             )
         else:
@@ -188,7 +188,7 @@ def unit_number(unit_name: str):
                 logger.warning(f"switchover failed with reason: {e}")
                 raise charm_refresh.PrecheckFailed("Unable to switch primary")
             else:
-                logging.info(
+                logger.info(
                     f"Switched primary to unit {last_unit_to_refresh} during pre-refresh check"
                 )
 
@@ -408,6 +408,7 @@ def set_unit_status(
                 json.dumps(refresh.unit_status_lower_priority().message)
             )
             return
+        logger.debug(f"Set unit status: {status}")
         self.unit.status = status
 
     def _reconcile_refresh_status(self, _=None):
@@ -464,17 +465,10 @@ def patroni_scrape_config(self) -> list[dict]:
     def app_units(self) -> set[Unit]:
         """The peer-related units in the application."""
         if not self._peers:
-            return set()
+            return {self.unit}
 
         return {self.unit, *self._peers.units}
 
-    def scoped_peer_data(self, scope: Scopes) -> dict | None:
-        """Returns peer data based on scope."""
-        if scope == APP_SCOPE:
-            return self.app_peer_data
-        elif scope == UNIT_SCOPE:
-            return self.unit_peer_data
-
     @property
     def app_peer_data(self) -> dict:
         """Application peer relation data object."""
@@ -607,7 +601,6 @@ def postgresql(self) -> PostgreSQL:
         """Returns an instance of the object used to interact with the database."""
         password = str(self.get_secret(APP_SCOPE, f"{USER}-password"))
         if self._postgresql is None or self._postgresql.primary_host is None:
-            logger.debug("Init class PostgreSQL")
             self._postgresql = PostgreSQL(
                 primary_host=self.primary_endpoint,
                 current_host=self._unit_ip,
@@ -628,21 +621,29 @@ 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)
+            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).
-            if not primary_endpoint or primary_endpoint not in self._units_ips:
-                # TODO figure out why peer data is not available
-                if primary_endpoint and len(self._units_ips) == 1 and len(self._peers.units) > 1:
-                    logger.warning(
-                        "Possibly incomplete peer data: Will not map primary IP to unit IP"
-                    )
-                    return primary_endpoint
-                logger.debug("primary endpoint early exit: Primary IP not in cached peer list.")
+            if not primary_endpoint:
+                logger.warning(f"Missing primary IP for {primary}")
                 primary_endpoint = None
+            elif primary_endpoint not in self._units_ips:
+                if len(self._peers.units) == 0:
+                    logger.info(f"The unit didn't join {PEER} relation? Using {primary_endpoint}")
+                elif len(self._units_ips) == 1 and len(self._peers.units) > 1:
+                    logger.warning(f"Possibly incomplete peer data, keep using {primary_endpoint}")
+                else:
+                    logger.debug("Early exit primary_endpoint: Primary IP not in cached peer list")
+                    primary_endpoint = None
+                logger.debug("primary_endpoint: %s", primary_endpoint)
+                logger.debug("self._units_ips: %s", self._units_ips)
+                logger.debug("self._peers.units len: %s", len(self._peers.units))
         except RetryError:
             return None
         else:
@@ -859,6 +860,11 @@ 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 event.unit is None:  # or event.unit == self.unit.name:
+            logger.debug(f"Early exit on_peer_relation_changed: event to itself ({event.unit})")
+            return False
+
         if not self.is_cluster_initialised:
             logger.debug("Early exit on_peer_relation_changed: cluster not initialized")
             return False
@@ -1065,13 +1071,15 @@ 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")
         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.
+        logger.debug(f"Add member {member_ip} to the members_ips list")
+        # It should be updated in each other member.
         self._add_to_members_ips(member_ip)
 
         # Update Patroni configuration file.
@@ -1176,10 +1184,14 @@ def _units_ips(self) -> set[str]:
             A list of peers addresses (strings).
         """
         # Get all members IPs and remove the current unit IP from the list.
+        for unit in self._peers.units:
+            logger.debug(f"_units_ips: unit {unit}")
         addresses = {self._get_unit_ip(unit) for unit in self._peers.units}
         addresses.add(self._unit_ip)
         if None in addresses:
+            logger.debug("_units_ips: Removing None")
             addresses.remove(None)
+        logger.debug(f"_units_ips: Final addresses {addresses}")
         return addresses
 
     @property
@@ -1310,7 +1322,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:
@@ -1413,10 +1425,8 @@ def _on_config_changed(self, event) -> None:  # noqa: C901
             return
 
         if self.refresh is None:
-            logger.debug("Defer on_config_changed: Refresh could be in progress")
-            event.defer()
-            return
-        if self.refresh.in_progress:
+            logger.warning("Warning _on_config_changed: Refresh could be in progress")
+        elif self.refresh.in_progress:
             logger.debug("Defer on_config_changed: Refresh in progress")
             event.defer()
             return
@@ -1488,14 +1498,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(
@@ -1507,8 +1520,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:
@@ -1538,10 +1553,8 @@ def _can_start(self, event: StartEvent) -> bool:
 
         # Safeguard against starting while refreshing.
         if self.refresh is None:
-            logger.debug("Defer on_start: Refresh could be in progress")
-            event.defer()
-            return False
-        if self.refresh.in_progress:
+            logger.warning("Warning on_start: Refresh could be in progress")
+        elif self.refresh.in_progress:
             # TODO: we should probably start workload if scale up while refresh in progress
             logger.debug("Defer on_start: Refresh in progress")
             event.defer()
@@ -1591,16 +1604,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.
+        logger.debug("Bootstrap the cluster in the leader unit")
         self._start_primary(event)
         self._restart_services_after_reboot()
 
     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()
@@ -1689,6 +1705,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
@@ -1697,14 +1715,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),
@@ -1767,16 +1785,15 @@ def _start_primary(self, event: StartEvent) -> None:
             event.defer()
             return
 
-        # Set the flag to enable the replicas to start the Patroni service.
+        logger.debug("Set the flag to enable the replicas to start the Patroni service")
         self._peers.data[self.app]["cluster_initialised"] = "True"
         # Flag to know if triggers need to be removed after refresh
         self._peers.data[self.app]["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())
@@ -2001,6 +2018,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():
@@ -2045,8 +2063,8 @@ def _handle_processes_failures(self) -> bool:
                 logger.info("PostgreSQL data directory was not empty. Moved pg_wal")
                 return True
             try:
-                self._patroni.restart_patroni()
                 logger.info("restarted PostgreSQL because it was not running")
+                self._patroni.restart_patroni()
                 return True
             except RetryError:
                 logger.error("failed to restart PostgreSQL after checking that it was not running")
@@ -2061,6 +2079,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"
@@ -2077,12 +2096,12 @@ def _set_primary_status_message(self) -> None:
                     danger_state = " (read-only)"
                 elif len(self._patroni.get_running_cluster_members()) < self.app.planned_units():
                     danger_state = " (degraded)"
-                self.set_unit_status(
-                    ActiveStatus(
-                        f"{'Standby' if self.is_standby_leader else 'Primary'}{danger_state}"
-                    )
-                )
+                unit_status = "Standby" if self.is_standby_leader else "Primary"
+                unit_status = unit_status + danger_state
+                logger.debug(f"Set ActiveStatus({unit_status})")
+                self.set_unit_status(ActiveStatus(f"{unit_status}"))
             elif self._patroni.member_started:
+                logger.debug("Set ActiveStatus()")
                 self.set_unit_status(ActiveStatus())
         except (RetryError, ConnectionError) as e:
             logger.error(f"failed to get primary with error {e}")
@@ -2286,13 +2305,16 @@ def _is_workload_running(self) -> bool:
     @property
     def _can_connect_to_postgresql(self) -> bool:
         try:
-            for attempt in Retrying(stop=stop_after_delay(30), wait=wait_fixed(3)):
+            for attempt in Retrying(stop=stop_after_delay(10), wait=wait_fixed(3)):
                 with attempt:
+                    logger.debug("Checking connection to PostgreSQL database...")
                     if not self.postgresql.get_postgresql_timezones():
+                        logger.debug("Cannot connect to database (CannotConnectError)")
                         raise CannotConnectError
         except RetryError:
-            logger.debug("Cannot connect to database")
+            logger.debug("Cannot connect to database (RetryError)")
             return False
+        logger.debug("Successfully connected to the database")
         return True
 
     def update_config(
@@ -2303,6 +2325,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
 
@@ -2396,6 +2419,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
 
@@ -2415,6 +2439,7 @@ def _validate_config_options(self) -> None:
         if not self.postgresql.validate_date_style(self.config.request_date_style):
             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")
 
@@ -2428,6 +2453,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()
         else: