Add logger

Author: vshepard

pg_probackup2/app.py

@@ -14,6 +14,9 @@
 from .storage.fs_backup import TestBackupDir, FSTestBackupDir
 from .gdb import GDBobj
 from .init_helpers import init_params
+from .logger import log_command, patch_testgres_command_logging
+
+patch_testgres_command_logging()
 
 warning = """
 Wrong splint in show_pb
@@ -123,8 +126,10 @@ def run(self, command, gdb=False, old_binary=False, return_id=True, env=None,
         command, strcommand = self._add_options(command, skip_log_directory)
 
         self.test_class.cmd = f"{binary_path} {strcommand}"
-        if self.verbose:
-            print(self.test_class.cmd)
+        # Always echo the command: it is captured by pytest and shown in failing
+        # test reports (like pg_probackup <= 2.5.11), and routed via the dedicated
+        # COMMAND log level. See pg_probackup2/logger.py.
+        log_command(self.test_class.cmd)
 
         cmdline = self._form_cmdline(binary_path, command)
 
@@ -773,8 +778,7 @@ def run_binary(self, command, asynchronous=False, env=None):
         if not env:
             env = self.test_env
 
-        if self.verbose:
-            print([' '.join(map(str, command))])
+        log_command(command)
         try:
             if asynchronous:
                 return subprocess.Popen(

pg_probackup2/gdb.py

@@ -5,6 +5,8 @@
 import unittest
 from time import sleep
 
+from .logger import log_command
+
 
 class GdbException(Exception):
     def __init__(self, message="False"):
@@ -56,8 +58,7 @@ def __init__(self, cmd, env, attach=False):
         else:
             self.cmd = self.base_cmd + ['--args'] + cmd
 
-        if self.verbose:
-            print([' '.join(map(str, self.cmd))])
+        log_command(self.cmd)
 
         self.proc = subprocess.Popen(
             self.cmd,

pg_probackup2/logger.py

@@ -0,0 +1,137 @@
+"""
+  Usage:
+    [pytest]
+    log_cli = true
+    log_cli_level = 25
+
+  or, without touching pytest config at all, by pointing the
+  ``PG_PROBACKUP_CMD_LOG`` environment variable at a file -- every executed
+  command is then appended there as a bare, copy-paste-into-a-shell line.
+"""
+
+import functools
+import logging
+import os
+
+# Dedicated level for command echoing.  Sits between INFO (20) and WARNING (30):
+# more prominent than ordinary INFO chatter, but it is not a warning.
+COMMAND = 25
+COMMAND_LEVEL_NAME = 'COMMAND'
+logging.addLevelName(COMMAND, COMMAND_LEVEL_NAME)
+
+cmd_logger = logging.getLogger('pg_probackup2.commands')
+
+
+def _command(self, message, *args, **kwargs):
+    if self.isEnabledFor(COMMAND):
+        self._log(COMMAND, message, args, **kwargs)
+
+
+# Convenience method: ``logging.getLogger(...).command("...")``.
+logging.Logger.command = _command
+
+_FILE_HANDLER_INSTALLED = False
+_TESTGRES_PATCHED = False
+
+
+def _maybe_add_file_handler():
+    """Attach a file handler to the command logger if PG_PROBACKUP_CMD_LOG is set."""
+    global _FILE_HANDLER_INSTALLED
+    if _FILE_HANDLER_INSTALLED:
+        return
+    _FILE_HANDLER_INSTALLED = True
+
+    path = os.environ.get('PG_PROBACKUP_CMD_LOG')
+    if not path:
+        return
+    handler = logging.FileHandler(path)
+    handler.setLevel(COMMAND)
+    # bare command line, one per row -- ready to paste into a shell script
+    handler.setFormatter(logging.Formatter('%(message)s'))
+    cmd_logger.addHandler(handler)
+    # make sure the dedicated logger lets COMMAND records reach the handler even
+    # if the root logger is configured at a higher level
+    if cmd_logger.level == logging.NOTSET or cmd_logger.level > COMMAND:
+        cmd_logger.setLevel(COMMAND)
+
+
+def log_command(cmd, to_stdout=True):
+    """Echo a command that is about to be (or has just been) executed.
+
+    Args:
+        cmd: the command, either a list/tuple of arguments or an already
+             assembled string.
+        to_stdout: also ``print()`` to stdout (default True) so the command is
+             visible in pytest's "Captured stdout call" section on failure.
+    """
+    _maybe_add_file_handler()
+
+    if isinstance(cmd, (list, tuple)):
+        line = ' '.join(map(str, cmd))
+    else:
+        line = str(cmd)
+
+    if to_stdout:
+        # historical 2.5.11 format: a single-element list, e.g. ['pg_probackup ...']
+        print([line])
+
+    # bare line for handlers/files (grep- and copy-paste-friendly)
+    cmd_logger.command('%s', line)
+
+
+def patch_testgres_command_logging():
+    """Echo testgres utility invocations (pg_ctl, initdb, pg_basebackup, ...) too.
+
+    testgres routes every external utility through ``utils.execute_utility2``.
+    Several submodules (``node``, ``cache``, ``backup``, ...) grab their own
+    reference at import time via ``from .utils import execute_utility2``, so it
+    is not enough to replace the function in ``utils``.  We therefore:
+
+      1. replace it in ``testgres.utils`` (so any *later* ``from .utils import``
+         picks up the wrapper), and
+      2. sweep every already-loaded ``testgres.*`` module and replace its
+         ``execute_utility2`` attribute when it still points at the original.
+
+    The wrapper only adds an echo and otherwise delegates unchanged, so it is
+    safe across testgres versions; any failure to patch is non-fatal.
+    """
+    global _TESTGRES_PATCHED
+    if _TESTGRES_PATCHED:
+        return
+    _TESTGRES_PATCHED = True
+
+    try:
+        import sys
+        import testgres.utils as tg_utils
+    except Exception as e:  # testgres missing/broken -- nothing to patch
+        logging.getLogger(__name__).debug(
+            "Could not patch testgres for command logging: %s", e)
+        return
+
+    original = getattr(tg_utils, 'execute_utility2', None)
+    if original is None or getattr(original, '_pb2_logging_wrapper', False):
+        return
+
+    @functools.wraps(original)
+    def wrapper(os_ops, args, *a, **kw):
+        try:
+            log_command(args)
+        except Exception:
+            # echoing must never break the actual command execution
+            pass
+        return original(os_ops, args, *a, **kw)
+
+    wrapper._pb2_logging_wrapper = True
+
+    # 1) the source module (covers future ``from .utils import execute_utility2``)
+    tg_utils.execute_utility2 = wrapper
+
+    # 2) every already-imported testgres submodule that copied the reference
+    for name, module in list(sys.modules.items()):
+        if module is None or not name.startswith('testgres'):
+            continue
+        try:
+            if getattr(module, 'execute_utility2', None) is original:
+                module.execute_utility2 = wrapper
+        except Exception:
+            pass