From ae97584218261f152fb22c9bfcfd99ad967b0e80 Mon Sep 17 00:00:00 2001
From: Thomas Waldmann <tw@waldmann-edv.de>
Date: Tue, 6 Jun 2023 18:02:36 +0200
Subject: [PATCH] fix logging, add some comments

shutting down logging is problematic as it is global
and we do multi-threaded execution, e.g. in tests.

thus, rather just flush the important loggers and keep
them alive.
---
 src/borg/logger.py                      | 30 +++++++++++++++++++++----
 src/borg/remote.py                      |  2 +-
 src/borg/testsuite/archiver/__init__.py |  6 ++---
 3 files changed, 30 insertions(+), 8 deletions(-)

diff --git a/src/borg/logger.py b/src/borg/logger.py
index f158aa797..3dc76a290 100644
--- a/src/borg/logger.py
+++ b/src/borg/logger.py
@@ -28,6 +28,24 @@ The way to use this is as follows:
 
 * what is output on INFO level is additionally controlled by commandline
   flags
+
+Logging setup is a bit complicated in borg, as it needs to work under misc. conditions:
+- purely local, not client/server (easy)
+- client/server: RemoteRepository ("borg serve" process) writes log records into a global
+  queue, which is then sent to the client side by the main serve loop (via the RPC protocol,
+  either over ssh stdout, more directly via process stdout without ssh [used in the tests]
+  or via a socket. On the client side, the log records are fed into the clientside logging
+  system. When remote_repo.close() is called, server side must send all queued log records
+  via the RPC channel before returning the close() call's return value (as the client will
+  then shut down the connection).
+- progress output is always given as json to the logger (including the plain text inside
+  the json), but then formatted by the logging system's formatter as either plain text or
+  json depending on the cli args given (--log-json?).
+- tests: potentially running in parallel via pytest-xdist, capturing borg output into a
+  given stream.
+- logging might be short-lived (e.g. when invoking a single borg command via the cli)
+  or long-lived (e.g. borg serve --socket or when running the tests)
+- logging is global and exists only once per process.
 """
 
 import inspect
@@ -115,10 +133,14 @@ def remove_handlers(logger):
         logger.removeHandler(handler)
 
 
-def teardown_logging():
-    global configured
-    logging.shutdown()
-    configured = False
+def flush_logging():
+    # make sure all log output is flushed,
+    # this is especially important for the "borg serve" RemoteRepository logging:
+    # all log output needs to be sent via the ssh / socket connection before closing it.
+    for logger_name in "borg.output.progress", "":
+        logger = logging.getLogger(logger_name)
+        for handler in logger.handlers:
+            handler.flush()
 
 
 def setup_logging(
diff --git a/src/borg/remote.py b/src/borg/remote.py
index 060dd261a..398c02456 100644
--- a/src/borg/remote.py
+++ b/src/borg/remote.py
@@ -366,7 +366,7 @@ class RepositoryServer:  # pragma: no cover
         if self.repository is not None:
             self.repository.__exit__(None, None, None)
             self.repository = None
-        borg.logger.teardown_logging()
+        borg.logger.flush_logging()
         self.send_queued_log()
 
     def inject_exception(self, kind):
diff --git a/src/borg/testsuite/archiver/__init__.py b/src/borg/testsuite/archiver/__init__.py
index 56b66a439..5882ab0d3 100644
--- a/src/borg/testsuite/archiver/__init__.py
+++ b/src/borg/testsuite/archiver/__init__.py
@@ -21,7 +21,7 @@ from ...constants import *  # NOQA
 from ...helpers import Location
 from ...helpers import EXIT_SUCCESS
 from ...helpers import bin_to_hex
-from ...logger import teardown_logging
+from ...logger import flush_logging
 from ...manifest import Manifest
 from ...remote import RemoteRepository
 from ...repository import Repository
@@ -83,9 +83,9 @@ def exec_cmd(*args, archiver=None, fork=False, exe=None, input=b"", binary_outpu
                 output_text.flush()
                 return e.code, output.getvalue() if binary_output else output.getvalue().decode()
             try:
-                ret = archiver.run(args)
+                ret = archiver.run(args)  # calls setup_logging internally
             finally:
-                teardown_logging()  # usually done via atexit, but we do not exit here
+                flush_logging()  # usually done via atexit, but we do not exit here
             output_text.flush()
             return ret, output.getvalue() if binary_output else output.getvalue().decode()
         finally: