new remote and progress logging, cleanups

src/borg/archiver/__init__.py

@@ -482,8 +482,9 @@ def run(self, args):
         func = get_func(args)
         # do not use loggers before this!
         is_serve = func == self.do_serve
-        self.log_json = args.log_json or is_serve
-        setup_logging(level=args.log_level, json=self.log_json)
+        self.log_json = args.log_json and not is_serve
+        func_name = getattr(func, "__name__", "none")
+        setup_logging(level=args.log_level, is_serve=is_serve, log_json=self.log_json, func=func_name)
         args.progress |= is_serve
         self._setup_implied_logging(vars(args))
         self._setup_topic_debugging(args)

src/borg/helpers/__init__.py

@@ -33,7 +33,7 @@
 from .process import daemonize, daemonizing
 from .process import signal_handler, raising_signal_handler, sig_int, ignore_sigint, SigHup, SigTerm
 from .process import popen_with_error_handling, is_terminal, prepare_subprocess_env, create_filter_process
-from .progress import ProgressIndicatorPercent, ProgressIndicatorEndless, ProgressIndicatorMessage
+from .progress import ProgressIndicatorPercent, ProgressIndicatorMessage
 from .time import parse_timestamp, timestamp, safe_timestamp, safe_s, safe_ns, MAX_S, SUPPORT_32BIT_PLATFORMS
 from .time import format_time, format_timedelta, OutputTimestamp, archive_ts_now
 from .yes_no import yes, TRUISH, FALSISH, DEFAULTISH

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,58 +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
-
-                    # 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)
-
-
-class ProgressIndicatorEndless:
-    def __init__(self, step=10, file=None):
-        """
-        Progress indicator (long row of dots)
-
-        :param step: every Nth call, call the func
-        :param file: output file, default: sys.stderr
-        """
-        self.counter = 0  # call counter
-        self.triggered = 0  # increases 1 per trigger event
-        self.step = step  # trigger every <step> calls
-        if file is None:
-            file = sys.stderr
-        self.file = file
-
-    def progress(self):
-        self.counter += 1
-        trigger = self.counter % self.step == 0
-        if trigger:
-            self.triggered += 1
-        return trigger
-
-    def show(self):
-        trigger = self.progress()
-        if trigger:
-            return self.output(self.triggered)
-
-    def output(self, triggered):
-        print(".", end="", file=self.file, flush=True)
+                return self.output(self.msg % tuple([pct] + info), info=info)
+            else:
+                return self.output(self.msg % pct)
 
-    def finish(self):
-        print(file=self.file)
+    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

@@ -36,9 +36,64 @@
 import logging.config
 import logging.handlers  # needed for handlers defined there being configurable in logging.conf file
 import os
+import queue
+import sys
+import time
+from typing import Optional
 import warnings
 
+logging_debugging_path: Optional[str] = None  # if set, write borg.logger debugging log to path/borg-*.log
+
 configured = False
+borg_serve_log_queue: queue.SimpleQueue = queue.SimpleQueue()
+
+
+class BorgQueueHandler(logging.handlers.QueueHandler):
+    """borg serve writes log record dicts to a borg_serve_log_queue"""
+
+    def prepare(self, record: logging.LogRecord) -> dict:
+        return dict(
+            # kwargs needed for LogRecord constructor:
+            name=record.name,
+            level=record.levelno,
+            pathname=record.pathname,
+            lineno=record.lineno,
+            msg=record.msg,
+            args=record.args,
+            exc_info=record.exc_info,
+            func=record.funcName,
+            sinfo=record.stack_info,
+        )
+
+
+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 ...')
@@ -53,14 +108,31 @@ def _log_warning(message, category, filename, lineno, file=None, line=None):
     logger.warning(msg)
 
 
-def setup_logging(stream=None, conf_fname=None, env_var="BORG_LOGGING_CONF", level="info", json=False):
+def remove_handlers(logger):
+    for handler in logger.handlers[:]:
+        handler.flush()
+        handler.close()
+        logger.removeHandler(handler)
+
+
+def teardown_logging():
+    global configured
+    logging.shutdown()
+    configured = False
+
+
+def setup_logging(
+    stream=None, conf_fname=None, env_var="BORG_LOGGING_CONF", level="info", is_serve=False, log_json=False, func=None
+):
     """setup logging module according to the arguments provided
 
     if conf_fname is given (or the config file name can be determined via
     the env_var, if given): load this logging configuration.
 
     otherwise, set up a stream handler logger on stderr (by default, if no
     stream is provided).
+
+    is_serve: are we setting up the logging for "borg serve"?
     """
     global configured
     err_msg = None
@@ -77,25 +149,56 @@ 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 = logging.StreamHandler(stream)
+    level = level.upper()
     fmt = "%(message)s"
-    formatter = JsonFormatter(fmt) if json else logging.Formatter(fmt)
+    formatter = JsonFormatter(fmt) if log_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.addHandler(handler)
-    logger.setLevel(level.upper())
+    logger = logging.getLogger()
+    remove_handlers(logger)
+    logger.setLevel(level)
+
+    if logging_debugging_path is not None:
+        # add an addtl. root handler for debugging purposes
+        log_fname = os.path.join(logging_debugging_path, f"borg-{'serve' if is_serve else 'client'}-root.log")
+        handler2 = logging.StreamHandler(open(log_fname, "a"))
+        handler2.setFormatter(formatter)
+        logger.addHandler(handler2)
+        logger.warning(f"--- {func} ---")  # only handler2 shall get this
+
+    logger.addHandler(handler)  # do this late, so handler is not added while debug handler is set up
+
+    bop_formatter = JSONProgressFormatter() if log_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")
+    remove_handlers(bop_logger)
+    bop_logger.setLevel("INFO")
+    bop_logger.propagate = False
+
+    if logging_debugging_path is not None:
+        # add an addtl. progress handler for debugging purposes
+        log_fname = os.path.join(logging_debugging_path, f"borg-{'serve' if is_serve else 'client'}-progress.log")
+        bop_handler2 = logging.StreamHandler(open(log_fname, "a"))
+        bop_handler2.setFormatter(bop_formatter)
+        bop_logger.addHandler(bop_handler2)
+        json_dict = dict(
+            message=f"--- {func} ---", operation=0, msgid="", type="progress_message", finished=False, time=time.time()
+        )
+        bop_logger.warning(json.dumps(json_dict))  # only bop_handler2 shall get this
+
+    bop_logger.addHandler(bop_handler)  # do this late, so bop_handler is not added while debug handler is set up
+
     configured = True
+
     logger = logging.getLogger(__name__)
     if err_msg:
         logger.warning(f'setup_logging for "{conf_fname}" failed with "{err_msg}".')