diff --git a/borg/logger.py b/borg/logger.py index f2350f8d7..c75aaef75 100644 --- a/borg/logger.py +++ b/borg/logger.py @@ -88,7 +88,7 @@ def setup_logging(stream=None, conf_fname=None, env_var='BORG_LOGGING_CONF', lev logger = logging.getLogger('') handler = logging.StreamHandler(stream) if is_serve: - fmt = '$LOG %(levelname)s Remote: %(message)s' + fmt = '$LOG %(levelname)s %(name)s Remote: %(message)s' else: fmt = '%(message)s' handler.setFormatter(logging.Formatter(fmt)) diff --git a/borg/remote.py b/borg/remote.py index 5444f05bf..72c26c5e1 100644 --- a/borg/remote.py +++ b/borg/remote.py @@ -301,7 +301,13 @@ class RemoteRepository: if line.startswith('$LOG '): _, level, msg = line.split(' ', 2) level = getattr(logging, level, logging.CRITICAL) # str -> int - logging.log(level, msg.rstrip()) + if msg.startswith('Remote:'): + # server format: '$LOG Remote: ' + logging.log(level, msg.rstrip()) + else: + # server format '$LOG Remote: ' + logname, msg = msg.split(' ', 1) + logging.getLogger(logname).log(level, msg.rstrip()) else: sys.stderr.write("Remote: " + line) if w: diff --git a/borg/testsuite/repository.py b/borg/testsuite/repository.py index aa935e322..2695a5cbe 100644 --- a/borg/testsuite/repository.py +++ b/borg/testsuite/repository.py @@ -1,3 +1,5 @@ +import io +import logging import os import shutil import sys @@ -7,7 +9,7 @@ from unittest.mock import patch from ..hashindex import NSIndex from ..helpers import Location, IntegrityError from ..locking import UpgradableLock, LockFailed -from ..remote import RemoteRepository, InvalidRPCMethod +from ..remote import RemoteRepository, InvalidRPCMethod, ConnectionClosedWithHint from ..repository import Repository from . import BaseTestCase @@ -389,3 +391,83 @@ class RemoteRepositoryCheckTestCase(RepositoryCheckTestCase): def test_crash_before_compact(self): # skip this test, we can't mock-patch a Repository class in another process! pass + + +class RemoteRepositoryLoggingStub(RemoteRepository): + """ run a remote command that just prints a logging-formatted message to + stderr, and stub out enough of RemoteRepository to avoid the resulting + exceptions """ + def __init__(self, *args, **kw): + self.msg = kw.pop('msg') + super().__init__(*args, **kw) + + def borg_cmd(self, cmd, testing): + return [sys.executable, '-c', 'import sys; print("{}", file=sys.stderr)'.format(self.msg), ] + + def __del__(self): + # clean up from exception without triggering assert + if self.p: + self.close() + + +class RemoteRepositoryLoggerTestCase(RepositoryTestCaseBase): + def setUp(self): + self.location = Location('__testsuite__:/doesntexist/repo') + self.stream = io.StringIO() + self.handler = logging.StreamHandler(self.stream) + logging.getLogger().handlers[:] = [self.handler] + logging.getLogger('borg.repository').handlers[:] = [] + logging.getLogger('borg.repository.foo').handlers[:] = [] + + def tearDown(self): + pass + + def create_repository(self, msg): + try: + RemoteRepositoryLoggingStub(self.location, msg=msg) + except ConnectionClosedWithHint: + # stub is dumb, so this exception expected + pass + + def test_old_format_messages(self): + self.handler.setLevel(logging.DEBUG) + logging.getLogger().setLevel(logging.DEBUG) + + self.create_repository("$LOG INFO Remote: old format message") + self.assert_equal(self.stream.getvalue(), 'Remote: old format message\n') + + def test_new_format_messages(self): + self.handler.setLevel(logging.DEBUG) + logging.getLogger().setLevel(logging.DEBUG) + + self.create_repository("$LOG INFO borg.repository Remote: new format message") + self.assert_equal(self.stream.getvalue(), 'Remote: new format message\n') + + def test_remote_messages_screened(self): + # default borg config for root logger + self.handler.setLevel(logging.WARNING) + logging.getLogger().setLevel(logging.WARNING) + + self.create_repository("$LOG INFO borg.repository Remote: new format info message") + self.assert_equal(self.stream.getvalue(), '') + + def test_info_to_correct_local_child(self): + logging.getLogger('borg.repository').setLevel(logging.INFO) + logging.getLogger('borg.repository.foo').setLevel(logging.INFO) + # default borg config for root logger + self.handler.setLevel(logging.WARNING) + logging.getLogger().setLevel(logging.WARNING) + + child_stream = io.StringIO() + child_handler = logging.StreamHandler(child_stream) + child_handler.setLevel(logging.INFO) + logging.getLogger('borg.repository').handlers[:] = [child_handler] + foo_stream = io.StringIO() + foo_handler = logging.StreamHandler(foo_stream) + foo_handler.setLevel(logging.INFO) + logging.getLogger('borg.repository.foo').handlers[:] = [foo_handler] + + self.create_repository("$LOG INFO borg.repository Remote: new format child message") + self.assert_equal(foo_stream.getvalue(), '') + self.assert_equal(child_stream.getvalue(), 'Remote: new format child message\n') + self.assert_equal(self.stream.getvalue(), '')