channel progress output via logging system

- simplify progress output (no \r, no terminal size related tweaks)
- emit progress output via the logging system (so it does not use stderr
  of borg serve)
- progress code always logs a json string, the json has all needed
  to either do json log output or plain text log output.
- use formatters to generate plain or json output from that.
- clean up setup_logging
- use a StderrHandler that always uses the **current** sys.stderr
- tweak TestPassphrase to not accidentally trigger just because of seeing 12 in output

src/borg/helpers/progress.py

@@ -1,28 +1,15 @@
 import logging
 import json
-import sys
 import time
-from shutil import get_terminal_size
 
 from ..logger import create_logger
 
 logger = create_logger()
 
-from .parseformat import ellipsis_truncate
-
-
-def justify_to_terminal_size(message):
-    terminal_space = get_terminal_size(fallback=(-1, -1))[0]
-    # justify only if we are outputting to a terminal
-    if terminal_space != -1:
-        return message.ljust(terminal_space)
-    return message
-
 
 class ProgressIndicatorBase:
     LOGGER = "borg.output.progress"
     JSON_TYPE: str = None
-    json = False
 
     operation_id_counter = 0
 
@@ -33,73 +20,27 @@ def operation_id(cls):
         return cls.operation_id_counter
 
     def __init__(self, msgid=None):
-        self.handler = None
         self.logger = logging.getLogger(self.LOGGER)
         self.id = self.operation_id()
         self.msgid = msgid
 
-        # If there are no handlers, set one up explicitly because the
-        # terminator and propagation needs to be set.  If there are,
-        # they must have been set up by BORG_LOGGING_CONF: skip setup.
-        if not self.logger.handlers:
-            self.handler = logging.StreamHandler(stream=sys.stderr)
-            self.handler.setLevel(logging.INFO)
-            logger = logging.getLogger("borg")
-            # Some special attributes on the borg logger, created by setup_logging
-            # But also be able to work without that
-            try:
-                formatter = logger.formatter
-                terminator = "\n" if logger.json else "\r"
-                self.json = logger.json
-            except AttributeError:
-                terminator = "\r"
-            else:
-                self.handler.setFormatter(formatter)
-            self.handler.terminator = terminator
-
-            self.logger.addHandler(self.handler)
-            if self.logger.level == logging.NOTSET:
-                self.logger.setLevel(logging.WARN)
-            self.logger.propagate = False
-
-        # If --progress is not set then the progress logger level will be WARN
-        # due to setup_implied_logging (it may be NOTSET with a logging config file,
-        # but the interactions there are generally unclear), so self.emit becomes
-        # False, which is correct.
-        # If --progress is set then the level will be INFO as per setup_implied_logging;
-        # note that this is always the case for serve processes due to a "args.progress |= is_serve".
-        # In this case self.emit is True.
-        self.emit = self.logger.getEffectiveLevel() == logging.INFO
-
-    def __del__(self):
-        if self.handler is not None:
-            self.logger.removeHandler(self.handler)
-            self.handler.close()
-
-    def output_json(self, *, finished=False, **kwargs):
-        assert self.json
-        if not self.emit:
-            return
+    def make_json(self, *, finished=False, **kwargs):
         kwargs.update(
             dict(operation=self.id, msgid=self.msgid, type=self.JSON_TYPE, finished=finished, time=time.time())
         )
-        print(json.dumps(kwargs), file=sys.stderr, flush=True)
+        return json.dumps(kwargs)
 
     def finish(self):
-        if self.json:
-            self.output_json(finished=True)
-        else:
-            self.output("")
+        j = self.make_json(message="", finished=True)
+        self.logger.info(j)
 
 
 class ProgressIndicatorMessage(ProgressIndicatorBase):
     JSON_TYPE = "progress_message"
 
     def output(self, msg):
-        if self.json:
-            self.output_json(message=msg)
-        else:
-            self.logger.info(justify_to_terminal_size(msg))
+        j = self.make_json(message=msg)
+        self.logger.info(j)
 
 
 class ProgressIndicatorPercent(ProgressIndicatorBase):
@@ -141,24 +82,11 @@ def show(self, current=None, increase=1, info=None):
         """
         pct = self.progress(current, increase)
         if pct is not None:
-            # truncate the last argument, if no space is available
             if info is not None:
-                if not self.json:
-                    from ..platform import swidth  # avoid circular import
+                return self.output(self.msg % tuple([pct] + info), info=info)
+            else:
+                return self.output(self.msg % pct)
 
-                    # no need to truncate if we're not outputting to a terminal
-                    terminal_space = get_terminal_size(fallback=(-1, -1))[0]
-                    if terminal_space != -1:
-                        space = terminal_space - swidth(self.msg % tuple([pct] + info[:-1] + [""]))
-                        info[-1] = ellipsis_truncate(info[-1], space)
-                return self.output(self.msg % tuple([pct] + info), justify=False, info=info)
-
-            return self.output(self.msg % pct)
-
-    def output(self, message, justify=True, info=None):
-        if self.json:
-            self.output_json(message=message, current=self.counter, total=self.total, info=info)
-        else:
-            if justify:
-                message = justify_to_terminal_size(message)
-            self.logger.info(message)
+    def output(self, message, info=None):
+        j = self.make_json(message=message, current=self.counter, total=self.total, info=info)
+        self.logger.info(j)

src/borg/logger.py

@@ -37,10 +37,11 @@
 import logging.handlers  # needed for handlers defined there being configurable in logging.conf file
 import os
 import queue
+import sys
 import warnings
 
 configured = False
-borg_serve_log_queue = queue.SimpleQueue()
+borg_serve_log_queue: queue.SimpleQueue = queue.SimpleQueue()
 
 
 class BorgQueueHandler(logging.handlers.QueueHandler):
@@ -61,6 +62,35 @@ def prepare(self, record: logging.LogRecord) -> dict:
         )
 
 
+class StderrHandler(logging.StreamHandler):
+    """
+    This class is like a StreamHandler using sys.stderr, but always uses
+    whatever sys.stderr is currently set to rather than the value of
+    sys.stderr at handler construction time.
+    """
+
+    def __init__(self, stream=None):
+        logging.Handler.__init__(self)
+
+    @property
+    def stream(self):
+        return sys.stderr
+
+
+class TextProgressFormatter(logging.Formatter):
+    def format(self, record: logging.LogRecord) -> str:
+        # record.msg contains json (because we always do json for progress log)
+        j = json.loads(record.msg)
+        # inside the json, the text log line can be found under "message"
+        return f"{j['message']}"
+
+
+class JSONProgressFormatter(logging.Formatter):
+    def format(self, record: logging.LogRecord) -> str:
+        # record.msg contains json (because we always do json for progress log)
+        return f"{record.msg}"
+
+
 # use something like this to ignore warnings:
 # warnings.filterwarnings('ignore', r'... regex for warning message to ignore ...')
 
@@ -100,25 +130,37 @@ def setup_logging(stream=None, conf_fname=None, env_var="BORG_LOGGING_CONF", lev
                 logging.config.fileConfig(f)
             configured = True
             logger = logging.getLogger(__name__)
-            borg_logger = logging.getLogger("borg")
-            borg_logger.json = json
             logger.debug(f'using logging configuration read from "{conf_fname}"')
             warnings.showwarning = _log_warning
             return None
         except Exception as err:  # XXX be more precise
             err_msg = str(err)
+
     # if we did not / not successfully load a logging configuration, fallback to this:
-    logger = logging.getLogger("")
-    handler = BorgQueueHandler(borg_serve_log_queue) if is_serve else logging.StreamHandler(stream)
+    level = level.upper()
     fmt = "%(message)s"
     formatter = JsonFormatter(fmt) if json else logging.Formatter(fmt)
+    SHandler = StderrHandler if stream is None else logging.StreamHandler
+    handler = BorgQueueHandler(borg_serve_log_queue) if is_serve else SHandler(stream)
     handler.setFormatter(formatter)
-    borg_logger = logging.getLogger("borg")
-    borg_logger.formatter = formatter
-    borg_logger.json = json
+    logger = logging.getLogger()
+    (h.close() for h in list(logger.handlers))
+    logger.handlers.clear()
     logger.addHandler(handler)
-    logger.setLevel(level.upper())
+    logger.setLevel(level)
+
+    bop_formatter = JSONProgressFormatter() if json else TextProgressFormatter()
+    bop_handler = BorgQueueHandler(borg_serve_log_queue) if is_serve else SHandler(stream)
+    bop_handler.setFormatter(bop_formatter)
+    bop_logger = logging.getLogger("borg.output.progress")
+    (h.close() for h in list(bop_logger.handlers))
+    bop_logger.handlers.clear()
+    bop_logger.addHandler(bop_handler)
+    bop_logger.setLevel("INFO")
+    bop_logger.propagate = False
+
     configured = True
+
     logger = logging.getLogger(__name__)
     if err_msg:
         logger.warning(f'setup_logging for "{conf_fname}" failed with "{err_msg}".')

src/borg/testsuite/archiver/__init__.py

@@ -22,7 +22,6 @@
 from ...helpers import EXIT_SUCCESS
 from ...helpers import bin_to_hex
 from ...manifest import Manifest
-from ...logger import setup_logging
 from ...remote import RemoteRepository
 from ...repository import Repository
 from .. import has_lchflags
@@ -155,7 +154,6 @@ def tearDown(self):
         os.chdir(self._old_wd)
         # note: ignore_errors=True as workaround for issue #862
         shutil.rmtree(self.tmpdir, ignore_errors=True)
-        setup_logging()
 
     def cmd(self, *args, **kw):
         exit_code = kw.pop("exit_code", 0)

src/borg/testsuite/archiver/check_cmd.py

@@ -1,4 +1,3 @@
-import logging
 import shutil
 import unittest
 from unittest.mock import patch
@@ -26,8 +25,6 @@ def test_check_usage(self):
         self.assert_in("Starting repository check", output)
         self.assert_in("Starting archive consistency check", output)
         self.assert_in("Checking segments", output)
-        # reset logging to new process default to avoid need for fork=True on next check
-        logging.getLogger("borg.output.progress").setLevel(logging.NOTSET)
         output = self.cmd(f"--repo={self.repository_location}", "check", "-v", "--repository-only", exit_code=0)
         self.assert_in("Starting repository check", output)
         self.assert_not_in("Starting archive consistency check", output)

src/borg/testsuite/helpers.py

@@ -998,65 +998,36 @@ def test_yes_env_output(capfd, monkeypatch):
     assert "yes" in err
 
 
-def test_progress_percentage_sameline(capfd, monkeypatch):
-    # run the test as if it was in a 4x1 terminal
-    monkeypatch.setenv("COLUMNS", "4")
-    monkeypatch.setenv("LINES", "1")
+def test_progress_percentage(capfd):
     pi = ProgressIndicatorPercent(1000, step=5, start=0, msg="%3.0f%%")
     pi.logger.setLevel("INFO")
     pi.show(0)
     out, err = capfd.readouterr()
-    assert err == "  0%\r"
+    assert err == "  0%\n"
     pi.show(420)
     pi.show(680)
     out, err = capfd.readouterr()
-    assert err == " 42%\r 68%\r"
+    assert err == " 42%\n 68%\n"
     pi.show(1000)
     out, err = capfd.readouterr()
-    assert err == "100%\r"
+    assert err == "100%\n"
     pi.finish()
     out, err = capfd.readouterr()
-    assert err == " " * 4 + "\r"
+    assert err == "\n"
 
 
-@pytest.mark.skipif(is_win32, reason="no working swidth() implementation on this platform")
-def test_progress_percentage_widechars(capfd, monkeypatch):
-    st = "スター・トレック"  # "startrek" :-)
-    assert swidth(st) == 16
-    path = "/カーク船長です。"  # "Captain Kirk"
-    assert swidth(path) == 17
-    spaces = " " * 4  # to avoid usage of "..."
-    width = len("100%") + 1 + swidth(st) + 1 + swidth(path) + swidth(spaces)
-    monkeypatch.setenv("COLUMNS", str(width))
-    monkeypatch.setenv("LINES", "1")
-    pi = ProgressIndicatorPercent(100, step=5, start=0, msg=f"%3.0f%% {st} %s")
-    pi.logger.setLevel("INFO")
-    pi.show(0, info=[path])
-    out, err = capfd.readouterr()
-    assert err == f"  0% {st} {path}{spaces}\r"
-    pi.show(100, info=[path])
-    out, err = capfd.readouterr()
-    assert err == f"100% {st} {path}{spaces}\r"
-    pi.finish()
-    out, err = capfd.readouterr()
-    assert err == " " * width + "\r"
-
-
-def test_progress_percentage_step(capfd, monkeypatch):
-    # run the test as if it was in a 4x1 terminal
-    monkeypatch.setenv("COLUMNS", "4")
-    monkeypatch.setenv("LINES", "1")
+def test_progress_percentage_step(capfd):
     pi = ProgressIndicatorPercent(100, step=2, start=0, msg="%3.0f%%")
     pi.logger.setLevel("INFO")
     pi.show()
     out, err = capfd.readouterr()
-    assert err == "  0%\r"
+    assert err == "  0%\n"
     pi.show()
     out, err = capfd.readouterr()
     assert err == ""  # no output at 1% as we have step == 2
     pi.show()
     out, err = capfd.readouterr()
-    assert err == "  2%\r"
+    assert err == "  2%\n"
 
 
 def test_progress_percentage_quiet(capfd):
@@ -1293,19 +1264,19 @@ def os_unlink(_):
 
 class TestPassphrase:
     def test_passphrase_new_verification(self, capsys, monkeypatch):
-        monkeypatch.setattr(getpass, "getpass", lambda prompt: "12aöäü")
+        monkeypatch.setattr(getpass, "getpass", lambda prompt: "1234aöäü")
         monkeypatch.setenv("BORG_DISPLAY_PASSPHRASE", "no")
         Passphrase.new()
         out, err = capsys.readouterr()
-        assert "12" not in out
-        assert "12" not in err
+        assert "1234" not in out
+        assert "1234" not in err
 
         monkeypatch.setenv("BORG_DISPLAY_PASSPHRASE", "yes")
         passphrase = Passphrase.new()
         out, err = capsys.readouterr()
-        assert "313261c3b6c3a4c3bc" not in out
-        assert "313261c3b6c3a4c3bc" in err
-        assert passphrase == "12aöäü"
+        assert "3132333461c3b6c3a4c3bc" not in out
+        assert "3132333461c3b6c3a4c3bc" in err
+        assert passphrase == "1234aöäü"
 
         monkeypatch.setattr(getpass, "getpass", lambda prompt: "1234/@=")
         Passphrase.new()