DPE-7726: Add Patroni API logging

Also:
* use commong logger everywhere
* and add several useful log messaged (e.g. DB connection)
* remove no longer necessary debug 'Init class PostgreSQL'
* align Patroni API requests style everhywhere
* add Patroni API duration to debug logs

Author: taurus-forever

lib/charms/postgresql_k8s/v1/postgresql.py

@@ -273,8 +273,11 @@ def _connect_to_database(
             raise PostgreSQLUndefinedHostError("Host not set")
         if not self.password:
             raise PostgreSQLUndefinedPasswordError("Password not set")
+
+        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

@@ -177,7 +177,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:
@@ -187,7 +187,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"
                 )
 
@@ -612,7 +612,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,
@@ -2475,7 +2474,9 @@ def _handle_postgresql_restart_need(self) -> None:
             logger.error(f"Reload patroni call failed! error: {e!s}")
 
         restart_pending = self._patroni.is_restart_pending()
-        logger.debug(f"Checking if restart pending: {restart_postgresql} or {restart_pending}")
+        logger.debug(
+            f"Checking if restart pending: TLS={restart_postgresql} or API={restart_pending}"
+        )
         restart_postgresql = restart_postgresql or restart_pending
 
         self.unit_peer_data.update({"tls": "enabled" if self.is_tls_enabled else ""})

src/cluster.py

@@ -274,7 +274,7 @@ def cluster_status(self, alternative_endpoints: list | None = None) -> list[Clus
         if response := self.parallel_patroni_get_request(
             f"/{PATRONI_CLUSTER_STATUS_ENDPOINT}", alternative_endpoints
         ):
-            logger.debug("Patroni cluster members: %s", response["members"])
+            logger.debug("API cluster_status: %s", response["members"])
             return response["members"]
         raise RetryError(
             last_attempt=Future.construct(1, Exception("Unable to reach any units"), True)
@@ -462,6 +462,7 @@ def get_patroni_health(self) -> dict[str, str]:
                     timeout=API_REQUEST_TIMEOUT,
                     auth=self._patroni_auth,
                 )
+                logger.debug("API get_patroni_health: %s (%s)", r, r.elapsed.total_seconds())
 
         return r.json()
 
@@ -529,15 +530,20 @@ def is_replication_healthy(self) -> bool:
                     for members_ip in members_ips:
                         endpoint = "leader" if members_ip == primary_ip else "replica?lag=16kB"
                         url = self._patroni_url.replace(self.unit_ip, members_ip)
-                        member_status = requests.get(
+                        r = requests.get(
                             f"{url}/{endpoint}",
                             verify=self.verify,
                             auth=self._patroni_auth,
                             timeout=PATRONI_TIMEOUT,
                         )
-                        if member_status.status_code != 200:
+                        logger.debug(
+                            "API is_replication_healthy: %s (%s)",
+                            r,
+                            r.elapsed.total_seconds(),
+                        )
+                        if r.status_code != 200:
                             logger.debug(
-                                f"Failed replication check for {members_ip} with code {member_status.status_code}"
+                                f"Failed replication check for {members_ip} with code {r.status_code}"
                             )
                             raise Exception
         except RetryError:
@@ -590,17 +596,20 @@ def is_member_isolated(self) -> bool:
         try:
             for attempt in Retrying(stop=stop_after_delay(10), wait=wait_fixed(3)):
                 with attempt:
-                    cluster_status = requests.get(
+                    r = requests.get(
                         f"{self._patroni_url}/{PATRONI_CLUSTER_STATUS_ENDPOINT}",
                         verify=self.verify,
                         timeout=API_REQUEST_TIMEOUT,
                         auth=self._patroni_auth,
                     )
+                    logger.debug(
+                        "API is_member_isolated: %s (%s)", r["members"], r.elapsed.total_seconds()
+                    )
         except RetryError:
             # Return False if it was not possible to get the cluster info. Try again later.
             return False
 
-        return len(cluster_status.json()["members"]) == 0
+        return len(r.json()["members"]) == 0
 
     def online_cluster_members(self) -> list[ClusterMember]:
         """Return list of online cluster members."""
@@ -631,15 +640,21 @@ def promote_standby_cluster(self) -> None:
             auth=self._patroni_auth,
             timeout=PATRONI_TIMEOUT,
         )
+        logger.debug(
+            "API promote_standby_cluster: %s (%s)",
+            config_response,
+            config_response.elapsed.total_seconds(),
+        )
         if "standby_cluster" not in config_response.json():
             raise StandbyClusterAlreadyPromotedError("standby cluster is already promoted")
-        requests.patch(
+        r = requests.patch(
             f"{self._patroni_url}/config",
             verify=self.verify,
             json={"standby_cluster": None},
             auth=self._patroni_auth,
             timeout=PATRONI_TIMEOUT,
         )
+        logger.debug("API promote_standby_cluster patch: %s (%s)", r, r.elapsed.total_seconds())
         for attempt in Retrying(stop=stop_after_delay(60), wait=wait_fixed(3)):
             with attempt:
                 if self.get_primary() is None:
@@ -846,6 +861,7 @@ def switchover(self, candidate: str | None = None) -> None:
                     auth=self._patroni_auth,
                     timeout=PATRONI_TIMEOUT,
                 )
+                logger.debug("API switchover: %s (%s)", r, r.elapsed.total_seconds())
 
         # Check whether the switchover was unsuccessful.
         if r.status_code != 200:
@@ -1012,12 +1028,14 @@ def remove_raft_member(self, member_ip: str) -> None:
     @retry(stop=stop_after_attempt(20), wait=wait_exponential(multiplier=1, min=2, max=10))
     def reload_patroni_configuration(self):
         """Reload Patroni configuration after it was changed."""
-        requests.post(
+        logger.debug("Reloading Patroni configuration...")
+        r = requests.post(
             f"{self._patroni_url}/reload",
             verify=self.verify,
             auth=self._patroni_auth,
             timeout=PATRONI_TIMEOUT,
         )
+        logger.debug("API reload_patroni_configuration: %s (%s)", r, r.elapsed.total_seconds())
 
     def is_patroni_running(self) -> bool:
         """Check if the Patroni service is running."""
@@ -1048,36 +1066,45 @@ def restart_patroni(self) -> bool:
     @retry(stop=stop_after_attempt(3), wait=wait_exponential(multiplier=1, min=2, max=10))
     def restart_postgresql(self) -> None:
         """Restart PostgreSQL."""
-        requests.post(
+        logger.debug("Restarting PostgreSQL...")
+        r = requests.post(
             f"{self._patroni_url}/restart",
             verify=self.verify,
             auth=self._patroni_auth,
             timeout=PATRONI_TIMEOUT,
         )
+        logger.debug("API restart_postgresql: %s (%s)", r, r.elapsed.total_seconds())
 
     @retry(stop=stop_after_attempt(3), wait=wait_exponential(multiplier=1, min=2, max=10))
     def reinitialize_postgresql(self) -> None:
         """Reinitialize PostgreSQL."""
-        requests.post(
+        logger.debug("Reinitializing PostgreSQL...")
+        r = requests.post(
             f"{self._patroni_url}/reinitialize",
             verify=self.verify,
             auth=self._patroni_auth,
             timeout=PATRONI_TIMEOUT,
         )
+        logger.debug("API reinitialize_postgresql: %s (%s)", r, r.elapsed.total_seconds())
 
     @retry(stop=stop_after_attempt(3), wait=wait_exponential(multiplier=1, min=2, max=10))
     def bulk_update_parameters_controller_by_patroni(self, parameters: dict[str, Any]) -> None:
         """Update the value of a parameter controller by Patroni.
 
         For more information, check https://patroni.readthedocs.io/en/latest/patroni_configuration.html#postgresql-parameters-controlled-by-patroni.
         """
-        requests.patch(
+        r = requests.patch(
             f"{self._patroni_url}/config",
             verify=self.verify,
             json={"postgresql": {"parameters": parameters}},
             auth=self._patroni_auth,
             timeout=PATRONI_TIMEOUT,
         )
+        logger.debug(
+            "API bulk_update_parameters_controller_by_patroni: %s (%s)",
+            r,
+            r.elapsed.total_seconds(),
+        )
 
     def ensure_slots_controller_by_patroni(self, slots: dict[str, str]) -> None:
         """Synchronises slots controlled by Patroni with the provided state by removing unneeded slots and creating new ones.
@@ -1093,6 +1120,11 @@ def ensure_slots_controller_by_patroni(self, slots: dict[str, str]) -> None:
                     timeout=PATRONI_TIMEOUT,
                     auth=self._patroni_auth,
                 )
+                logger.debug(
+                    "API ensure_slots_controller_by_patroni: %s (%s)",
+                    current_config,
+                    current_config.elapsed.total_seconds(),
+                )
                 if current_config.status_code != 200:
                     raise Exception(
                         f"Failed to get current Patroni config: {current_config.status_code} {current_config.text}"
@@ -1106,13 +1138,18 @@ def ensure_slots_controller_by_patroni(self, slots: dict[str, str]) -> None:
                 "plugin": "pgoutput",
                 "type": "logical",
             }
-        requests.patch(
+        r = requests.patch(
             f"{self._patroni_url}/config",
             verify=self.verify,
             json={"slots": slots_patch},
             auth=self._patroni_auth,
             timeout=PATRONI_TIMEOUT,
         )
+        logger.debug(
+            "API ensure_slots_controller_by_patroni: %s (%s)",
+            r,
+            r.elapsed.total_seconds(),
+        )
 
     @property
     def _synchronous_node_count(self) -> int:
@@ -1140,6 +1177,9 @@ def update_synchronous_node_count(self) -> None:
                     auth=self._patroni_auth,
                     timeout=PATRONI_TIMEOUT,
                 )
+                logger.debug(
+                    "API update_synchronous_node_count: %s (%s)", r, r.elapsed.total_seconds()
+                )
 
                 # Check whether the update was unsuccessful.
                 if r.status_code != 200: