diff --git a/src/borg/archiver/__init__.py b/src/borg/archiver/__init__.py index 915594d1b..f9cad6179 100644 --- a/src/borg/archiver/__init__.py +++ b/src/borg/archiver/__init__.py @@ -483,7 +483,8 @@ class Archiver( # do not use loggers before this! is_serve = func == self.do_serve self.log_json = args.log_json and not is_serve - setup_logging(level=args.log_level, is_serve=is_serve, json=self.log_json) + 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) diff --git a/src/borg/logger.py b/src/borg/logger.py index a3049ea92..f158aa797 100644 --- a/src/borg/logger.py +++ b/src/borg/logger.py @@ -38,8 +38,12 @@ import logging.handlers # needed for handlers defined there being configurable 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() @@ -117,7 +121,9 @@ def teardown_logging(): configured = False -def setup_logging(stream=None, conf_fname=None, env_var="BORG_LOGGING_CONF", level="info", is_serve=False, json=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 @@ -152,24 +158,45 @@ def setup_logging(stream=None, conf_fname=None, env_var="BORG_LOGGING_CONF", lev # if we did not / not successfully load a logging configuration, fallback to this: 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) logger = logging.getLogger() remove_handlers(logger) - logger.addHandler(handler) logger.setLevel(level) - bop_formatter = JSONProgressFormatter() if json else TextProgressFormatter() + 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.addHandler(bop_handler) 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__)