Reapply "Standardize pgBackRest logging to use stderr consistently"

This reverts commit 1c3eb04.

Signed-off-by: Marcelo Henrique Neppel <marcelo.neppel@canonical.com>

Author: marceloneppel

src/backups.py

@@ -39,6 +39,7 @@
     PGBACKREST_CONF_PATH,
     PGBACKREST_CONFIGURATION_FILE,
     PGBACKREST_EXECUTABLE,
+    PGBACKREST_LOG_LEVEL_STDERR,
     PGBACKREST_LOGROTATE_FILE,
     PGBACKREST_LOGS_PATH,
     POSTGRESQL_DATA_PATH,
@@ -184,7 +185,13 @@ def can_use_s3_repository(self) -> tuple[bool, str]:
 
         try:
             return_code, stdout, stderr = self._execute_command(
-                [PGBACKREST_EXECUTABLE, PGBACKREST_CONFIGURATION_FILE, "info", "--output=json"],
+                [
+                    PGBACKREST_EXECUTABLE,
+                    PGBACKREST_CONFIGURATION_FILE,
+                    PGBACKREST_LOG_LEVEL_STDERR,
+                    "info",
+                    "--output=json",
+                ],
                 timeout=30,
             )
         except TimeoutExpired as e:
@@ -196,7 +203,7 @@ def can_use_s3_repository(self) -> tuple[bool, str]:
 
         else:
             if return_code != 0:
-                extracted_error = self._extract_error_message(stdout, stderr)
+                extracted_error = self._extract_error_message(stderr)
                 logger.error(f"Failed to run pgbackrest: {extracted_error}")
                 return False, FAILED_TO_INITIALIZE_STANZA_ERROR_MESSAGE
 
@@ -360,23 +367,25 @@ def _execute_command(
         return process.returncode, process.stdout.decode(), process.stderr.decode()
 
     @staticmethod
-    def _extract_error_message(stdout: str, stderr: str) -> str:
-        """Extract key error message from pgBackRest output.
+    def _extract_error_message(stderr: str) -> str:
+        """Extract key error message from pgBackRest stderr output.
+
+        Since we standardize all pgBackRest commands to use --log-level-stderr=warn,
+        all errors and warnings are consistently written to stderr. This makes error
+        extraction predictable and avoids potential log duplication issues.
 
         Args:
-            stdout: Standard output from pgBackRest command.
-            stderr: Standard error from pgBackRest command.
+            stderr: Standard error from pgBackRest command containing errors/warnings.
 
         Returns:
-            Extracted error message, prioritizing ERROR/WARN lines from output.
+            Extracted error message from stderr, prioritizing ERROR/WARN lines.
         """
-        combined_output = f"{stdout}\n{stderr}".strip()
-        if not combined_output:
+        if not stderr.strip():
             return f"Unknown error occurred. Please check the logs at {PGBACKREST_LOGS_PATH}"
 
-        # Extract lines with ERROR or WARN markers from pgBackRest output
+        # Extract lines with ERROR or WARN markers from pgBackRest stderr output
         error_lines = []
-        for line in combined_output.splitlines():
+        for line in stderr.splitlines():
             if "ERROR:" in line or "WARN:" in line:
                 # Clean up the line by removing debug prefixes like "P00  ERROR:"
                 cleaned = re.sub(r"^.*?(ERROR:|WARN:)", r"\1", line).strip()
@@ -386,13 +395,8 @@ def _extract_error_message(stdout: str, stderr: str) -> str:
         if error_lines:
             return "; ".join(error_lines)
 
-        # Otherwise return the last non-empty line from stderr or stdout
-        if stderr.strip():
-            return stderr.strip().splitlines()[-1]
-        if stdout.strip():
-            return stdout.strip().splitlines()[-1]
-
-        return f"Unknown error occurred. Please check the logs at {PGBACKREST_LOGS_PATH}"
+        # Otherwise return the last non-empty line from stderr
+        return stderr.strip().splitlines()[-1]
 
     def _format_backup_list(self, backup_list) -> str:
         """Formats provided list of backups as a table."""
@@ -438,11 +442,12 @@ def _generate_backup_list_output(self) -> str:
         return_code, output, stderr = self._execute_command([
             PGBACKREST_EXECUTABLE,
             PGBACKREST_CONFIGURATION_FILE,
+            PGBACKREST_LOG_LEVEL_STDERR,
             "info",
             "--output=json",
         ])
         if return_code != 0:
-            extracted_error = self._extract_error_message(output, stderr)
+            extracted_error = self._extract_error_message(stderr)
             raise ListBackupsError(f"Failed to list backups with error: {extracted_error}")
 
         backups = json.loads(output)[0]["backup"]
@@ -510,11 +515,12 @@ def _list_backups(self, show_failed: bool, parse=True) -> dict[str, tuple[str, s
         return_code, output, stderr = self._execute_command([
             PGBACKREST_EXECUTABLE,
             PGBACKREST_CONFIGURATION_FILE,
+            PGBACKREST_LOG_LEVEL_STDERR,
             "info",
             "--output=json",
         ])
         if return_code != 0:
-            extracted_error = self._extract_error_message(output, stderr)
+            extracted_error = self._extract_error_message(stderr)
             raise ListBackupsError(f"Failed to list backups with error: {extracted_error}")
 
         repository_info = next(iter(json.loads(output)), None)
@@ -545,12 +551,13 @@ def _list_timelines(self) -> dict[str, tuple[str, str]]:
         return_code, output, stderr = self._execute_command([
             PGBACKREST_EXECUTABLE,
             PGBACKREST_CONFIGURATION_FILE,
+            PGBACKREST_LOG_LEVEL_STDERR,
             "repo-ls",
             "--recurse",
             "--output=json",
         ])
         if return_code != 0:
-            extracted_error = self._extract_error_message(output, stderr)
+            extracted_error = self._extract_error_message(stderr)
             raise ListBackupsError(f"Failed to list repository with error: {extracted_error}")
 
         repository = json.loads(output).items()
@@ -663,6 +670,7 @@ def _initialise_stanza(self, event: HookEvent) -> bool:
                     return_code, _, stderr = self._execute_command([
                         PGBACKREST_EXECUTABLE,
                         PGBACKREST_CONFIGURATION_FILE,
+                        PGBACKREST_LOG_LEVEL_STDERR,
                         f"--stanza={self.stanza_name}",
                         "stanza-create",
                     ])
@@ -721,14 +729,15 @@ def check_stanza(self) -> bool:
                     return_code, stdout, stderr = self._execute_command([
                         PGBACKREST_EXECUTABLE,
                         PGBACKREST_CONFIGURATION_FILE,
+                        PGBACKREST_LOG_LEVEL_STDERR,
                         f"--stanza={self.stanza_name}",
                         "check",
                     ])
                     if return_code == PGBACKREST_ARCHIVE_TIMEOUT_ERROR_CODE:
                         # Raise an error if the archive command timeouts, so the user has the possibility
                         # to fix network issues and call juju resolve to re-trigger the hook that calls
                         # this method.
-                        extracted_error = self._extract_error_message(stdout, stderr)
+                        extracted_error = self._extract_error_message(stderr)
                         logger.error(
                             f"error: {extracted_error} - please fix the error and call juju resolve on this unit"
                         )
@@ -787,12 +796,13 @@ def _is_primary_pgbackrest_service_running(self) -> bool:
             return False
         return_code, stdout, stderr = self._execute_command([
             PGBACKREST_EXECUTABLE,
+            PGBACKREST_LOG_LEVEL_STDERR,
             "server-ping",
             "--io-timeout=10",
             self.charm.primary_endpoint,
         ])
         if return_code != 0:
-            extracted_error = self._extract_error_message(stdout, stderr)
+            extracted_error = self._extract_error_message(stderr)
             logger.warning(
                 f"Failed to contact pgBackRest TLS server on {self.charm.primary_endpoint} with error {extracted_error}"
             )
@@ -984,8 +994,8 @@ def _run_backup(
         command = [
             PGBACKREST_EXECUTABLE,
             PGBACKREST_CONFIGURATION_FILE,
+            PGBACKREST_LOG_LEVEL_STDERR,
             f"--stanza={self.stanza_name}",
-            "--log-level-console=debug",
             f"--type={BACKUP_TYPE_OVERRIDES[backup_type]}",
             "backup",
         ]
@@ -1020,7 +1030,7 @@ def _run_backup(
                 f"backup/{self.stanza_name}/{backup_id}/backup.log",
                 s3_parameters,
             )
-            extracted_error = self._extract_error_message(stdout, stderr)
+            extracted_error = self._extract_error_message(stderr)
             error_message = f"Failed to backup PostgreSQL with error: {extracted_error}"
             logger.error(f"Backup failed: {error_message}")
             event.fail(error_message)
@@ -1188,7 +1198,7 @@ def _on_restore_action(self, event):  # noqa: C901
             timeout=10,
         )
         if return_code != 0:
-            extracted_error = self._extract_error_message(stdout, stderr)
+            extracted_error = self._extract_error_message(stderr)
             error_message = (
                 f"Failed to remove previous cluster information with error: {extracted_error}"
             )

src/constants.py

@@ -26,6 +26,12 @@
 
 # Snap constants.
 PGBACKREST_EXECUTABLE = "charmed-postgresql.pgbackrest"
+# pgBackRest logging configuration
+# We use stderr for all error/warning output to have a consistent, predictable error extraction
+# mechanism. By default, pgBackRest uses stdout (console) for warnings, but we standardize on
+# stderr to avoid potential log duplication and to make error handling more reliable.
+# Reference: https://pgbackrest.org/configuration.html#section-log
+PGBACKREST_LOG_LEVEL_STDERR = "--log-level-stderr=warn"
 # pgBackRest error codes
 PGBACKREST_ARCHIVE_TIMEOUT_ERROR_CODE = (
     82  # Archive timeout - unable to archive WAL files within configured timeout period

tests/unit/test_backups.py

@@ -37,79 +37,57 @@ def harness():
     harness.cleanup()
 
 
-def test_extract_error_message_with_error_in_stdout():
-    """Test extracting error from stdout with ERROR marker."""
-    stdout = """2025-11-07 07:21:11.120 P00  ERROR: [056]: unable to find primary cluster - cannot proceed
+def test_extract_error_message_with_error_in_stderr():
+    """Test extracting error from stderr with ERROR marker."""
+    stderr = """2025-11-07 07:21:11.120 P00  ERROR: [056]: unable to find primary cluster - cannot proceed
                                     HINT: are all available clusters in recovery?"""
-    stderr = ""
-    result = PostgreSQLBackups._extract_error_message(stdout, stderr)
+    result = PostgreSQLBackups._extract_error_message(stderr)
     assert result == "ERROR: [056]: unable to find primary cluster - cannot proceed"
 
 
-def test_extract_error_message_with_error_in_stderr():
+def test_extract_error_message_with_plain_stderr():
     """Test extracting error from stderr when no ERROR marker."""
-    stdout = ""
     stderr = "Connection refused: cannot connect to S3"
-    result = PostgreSQLBackups._extract_error_message(stdout, stderr)
+    result = PostgreSQLBackups._extract_error_message(stderr)
     assert result == "Connection refused: cannot connect to S3"
 
 
-def test_extract_error_message_with_both_stdout_and_stderr():
-    """Test extracting error when ERROR marker is in stdout and stderr has additional info."""
-    stdout = "P00  ERROR: database error occurred"
-    stderr = "Additional stderr info"
-    result = PostgreSQLBackups._extract_error_message(stdout, stderr)
-    assert result == "ERROR: database error occurred"
-
-
 def test_extract_error_message_with_warning():
-    """Test extracting warning message from output."""
-    stdout = "P00  WARN: configuration issue detected"
-    stderr = ""
-    result = PostgreSQLBackups._extract_error_message(stdout, stderr)
+    """Test extracting warning message from stderr."""
+    stderr = "P00  WARN: configuration issue detected"
+    result = PostgreSQLBackups._extract_error_message(stderr)
     assert result == "WARN: configuration issue detected"
 
 
 def test_extract_error_message_with_multiple_errors():
-    """Test extracting multiple ERROR/WARN lines."""
-    stdout = """P00 ERROR: first error
+    """Test extracting multiple ERROR/WARN lines from stderr."""
+    stderr = """P00 ERROR: first error
 P00 WARN: warning message
 P00 ERROR: second error"""
-    stderr = ""
-    result = PostgreSQLBackups._extract_error_message(stdout, stderr)
+    result = PostgreSQLBackups._extract_error_message(stderr)
     assert result == "ERROR: first error; WARN: warning message; ERROR: second error"
 
 
 def test_extract_error_message_with_empty_output():
-    """Test with empty stdout and stderr returns helpful message."""
-    result = PostgreSQLBackups._extract_error_message("", "")
+    """Test with empty stderr returns helpful message."""
+    result = PostgreSQLBackups._extract_error_message("")
     assert (
         result
         == "Unknown error occurred. Please check the logs at /var/snap/charmed-postgresql/common/var/log/pgbackrest"
     )
 
 
-def test_extract_error_message_fallback_to_stdout_last_line():
-    """Test fallback to last line of stdout when no ERROR/WARN markers."""
-    stdout = "Some generic output\nMore details here\nFinal error message"
-    stderr = ""
-    result = PostgreSQLBackups._extract_error_message(stdout, stderr)
-    assert result == "Final error message"
-
-
 def test_extract_error_message_fallback_to_stderr_last_line():
-    """Test fallback to last line of stderr when no ERROR/WARN markers and no stdout."""
-    stdout = ""
+    """Test fallback to last line of stderr when no ERROR/WARN markers."""
     stderr = "Line 1\nLine 2\nFinal error message"
-    result = PostgreSQLBackups._extract_error_message(stdout, stderr)
+    result = PostgreSQLBackups._extract_error_message(stderr)
     assert result == "Final error message"
 
 
 def test_extract_error_message_cleans_debug_prefix():
     """Test that debug prefixes like 'P00  ERROR:' are cleaned up."""
-    stdout = "2025-11-07 07:21:11.120 P00  ERROR: test error message"
-    stderr = ""
-    result = PostgreSQLBackups._extract_error_message(stdout, stderr)
+    stderr = "2025-11-07 07:21:11.120 P00  ERROR: test error message"
+    result = PostgreSQLBackups._extract_error_message(stderr)
     assert result == "ERROR: test error message"