From fc105b49b1805586b3d7880266a5e310078f818b Mon Sep 17 00:00:00 2001 From: Marian Beermann Date: Wed, 17 May 2017 17:17:15 +0200 Subject: [PATCH 1/5] fix --progress and logging in general for remote --- src/borg/archiver.py | 20 ++++---- src/borg/helpers.py | 8 +++ src/borg/logger.py | 12 ++++- src/borg/remote.py | 83 +++++++++++++++++++++++++++----- src/borg/testsuite/repository.py | 1 + 5 files changed, 100 insertions(+), 24 deletions(-) diff --git a/src/borg/archiver.py b/src/borg/archiver.py index 0ddfe1fe5..9946dd471 100644 --- a/src/borg/archiver.py +++ b/src/borg/archiver.py @@ -3815,15 +3815,15 @@ class Archiver: """ turn on INFO level logging for args that imply that they will produce output """ # map of option name to name of logger for that option option_logger = { - 'output_list': 'borg.output.list', - 'show_version': 'borg.output.show-version', - 'show_rc': 'borg.output.show-rc', - 'stats': 'borg.output.stats', - 'progress': 'borg.output.progress', - } + 'output_list': 'borg.output.list', + 'show_version': 'borg.output.show-version', + 'show_rc': 'borg.output.show-rc', + 'stats': 'borg.output.stats', + 'progress': 'borg.output.progress', + } for option, logger_name in option_logger.items(): - if args.get(option, False): - logging.getLogger(logger_name).setLevel('INFO') + option_set = args.get(option, False) + logging.getLogger(logger_name).setLevel('INFO' if option_set else 'WARN') def _setup_topic_debugging(self, args): """Turn on DEBUG level logging for specified --debug-topics.""" @@ -3839,8 +3839,10 @@ class Archiver: # This works around http://bugs.python.org/issue9351 func = getattr(args, 'func', None) or getattr(args, 'fallback_func') # do not use loggers before this! - setup_logging(level=args.log_level, is_serve=func == self.do_serve, json=args.log_json) + is_serve = func == self.do_serve + setup_logging(level=args.log_level, is_serve=is_serve, json=args.log_json) self.log_json = args.log_json + args.progress |= is_serve self._setup_implied_logging(vars(args)) self._setup_topic_debugging(args) if args.show_version: diff --git a/src/borg/helpers.py b/src/borg/helpers.py index ec06946ee..a93ba710c 100644 --- a/src/borg/helpers.py +++ b/src/borg/helpers.py @@ -1226,6 +1226,14 @@ class ProgressIndicatorBase: 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): diff --git a/src/borg/logger.py b/src/borg/logger.py index 6300776d7..69cb86f18 100644 --- a/src/borg/logger.py +++ b/src/borg/logger.py @@ -88,15 +88,21 @@ 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: logger = logging.getLogger('') handler = logging.StreamHandler(stream) - if is_serve: + if is_serve and not json: fmt = '$LOG %(levelname)s %(name)s Remote: %(message)s' else: fmt = '%(message)s' - formatter = JsonFormatter(fmt) if json and not is_serve else logging.Formatter(fmt) + formatter = JsonFormatter(fmt) if json else logging.Formatter(fmt) handler.setFormatter(formatter) borg_logger = logging.getLogger('borg') borg_logger.formatter = formatter borg_logger.json = json + if configured and logger.handlers: + # The RepositoryServer can call setup_logging a second time to adjust the output + # mode from text-ish is_serve to json is_serve. + # Thus, remove the previously installed handler, if any. + logger.handlers[0].close() + logger.handlers.clear() logger.addHandler(handler) logger.setLevel(level.upper()) configured = True @@ -224,6 +230,8 @@ class JsonFormatter(logging.Formatter): data = { 'type': 'log_message', 'time': record.created, + 'message': '', + 'levelname': 'CRITICAL', } for attr in self.RECORD_ATTRIBUTES: value = getattr(record, attr, None) diff --git a/src/borg/remote.py b/src/borg/remote.py index c32ba9e6a..3cd4cb938 100644 --- a/src/borg/remote.py +++ b/src/borg/remote.py @@ -2,29 +2,30 @@ import errno import fcntl import functools import inspect +import json import logging import os import select import shlex import sys import tempfile -import traceback import textwrap import time +import traceback from subprocess import Popen, PIPE import msgpack from . import __version__ from .helpers import Error, IntegrityError -from .helpers import get_home_dir -from .helpers import sysinfo from .helpers import bin_to_hex -from .helpers import replace_placeholders +from .helpers import get_home_dir from .helpers import hostname_is_unique +from .helpers import replace_placeholders +from .helpers import sysinfo +from .logger import create_logger, setup_logging from .repository import Repository, MAX_OBJECT_SIZE, LIST_SCAN_LIMIT from .version import parse_version, format_version -from .logger import create_logger logger = create_logger(__name__) @@ -312,6 +313,9 @@ class RepositoryServer: # pragma: no cover # clients since 1.1.0b3 use a dict as client_data if isinstance(client_data, dict): self.client_version = client_data[b'client_version'] + level = logging.getLevelName(logging.getLogger('').level) + setup_logging(is_serve=True, json=True, level=level) + logger.debug('Initialized loggin system for new protocol') else: self.client_version = BORG_VERSION # seems to be newer than current version (no known old format) @@ -646,12 +650,6 @@ This problem will go away as soon as the server has been upgraded to 1.0.7+. opts.append('--critical') else: raise ValueError('log level missing, fix this code') - try: - borg_logger = logging.getLogger('borg') - if borg_logger.json: - opts.append('--log-json') - except AttributeError: - pass env_vars = [] if not hostname_is_unique(): env_vars.append('BORG_HOSTNAME_IS_UNIQUE=no') @@ -930,7 +928,58 @@ This problem will go away as soon as the server has been upgraded to 1.0.7+. def handle_remote_line(line): - if line.startswith('$LOG '): + """ + Handle a remote log line. + + This function is remarkably complex because it handles three different wire formats. + """ + if line.startswith('{'): + # This format is used by Borg since 1.1.0b6 for new-protocol clients. + # It is the same format that is exposed by --log-json. + msg = json.loads(line) + + if msg['type'] not in ('progress_message', 'progress_percent', 'log_message'): + logger.warning('Dropped remote log message with unknown type %r: %s', msg['type'], line) + return + + if msg['type'] == 'log_message': + # Re-emit log messages on the same level as the remote to get correct log suppression and verbosity. + level = getattr(logging, msg['levelname'], logging.CRITICAL) + assert isinstance(level, int) + target_logger = logging.getLogger(msg['name']) + # We manually check whether the log message should be propagated + if level >= target_logger.getEffectiveLevel() and logging.getLogger('borg').json: + sys.stderr.write(line) + else: + target_logger.log(level, '%s', msg['message']) + elif msg['type'].startswith('progress_') and not msg.get('finished'): + # Progress messages are a bit more complex. + # First of all, we check whether progress output is enabled. This is signalled + # through the effective level of the borg.output.progress logger + # (also see ProgressIndicatorBase in borg.helpers). + progress_logger = logging.getLogger('borg.output.progress') + if progress_logger.getEffectiveLevel() == logging.INFO: + # When progress output is enabled, then we check whether the client is in + # --log-json mode, as signalled by the "json" attribute on the "borg" logger. + if logging.getLogger('borg').json: + # In --log-json mode we directly re-emit the progress line as sent by the server. + sys.stderr.write(line) + else: + # In text log mode we write only the message to stderr and terminate with \r + # (carriage return, i.e. move the write cursor back to the beginning of the line) + # so that the next message, progress or not, overwrites it. This mirrors the behaviour + # of local progress displays. + sys.stderr.write(msg['message'] + '\r') + elif line.startswith('$LOG '): + # This format is used by Borg since 1.1.0b1. + # It prefixed log lines with $LOG as a marker, followed by the log level + # and optionally a logger name, then "Remote:" as a separator followed by the original + # message. + # + # It is the oldest format supported by these servers, so it was important to make + # it readable with older (1.0.x) clients. + # + # TODO: Remove this block (so it'll be handled by the "else:" below) with a Borg 1.1 RC. _, level, msg = line.split(' ', 2) level = getattr(logging, level, logging.CRITICAL) # str -> int if msg.startswith('Remote:'): @@ -941,7 +990,15 @@ def handle_remote_line(line): logname, msg = msg.split(' ', 1) logging.getLogger(logname).log(level, msg.rstrip()) else: - sys.stderr.write('Remote: ' + line) + # Plain 1.0.x and older format - re-emit to stderr (mirroring what the 1.0.x + # client did) or as a generic log message. + # We don't know what priority the line had. + if logging.getLogger('borg').json: + logging.getLogger('').warning('Remote: ' + line.strip()) + else: + # In non-JSON mode we circumvent logging to preserve carriage returns (\r) + # which are generated by remote progress displays. + sys.stderr.write('Remote: ' + line) class RepositoryNoCache: diff --git a/src/borg/testsuite/repository.py b/src/borg/testsuite/repository.py index 2819c64cd..192f8d3ea 100644 --- a/src/borg/testsuite/repository.py +++ b/src/borg/testsuite/repository.py @@ -714,6 +714,7 @@ class RemoteRepositoryTestCase(RepositoryTestCase): class MockArgs: remote_path = 'borg' umask = 0o077 + debug_topics = [] assert self.repository.borg_cmd(None, testing=True) == [sys.executable, '-m', 'borg.archiver', 'serve'] args = MockArgs() From 18a2902c9c0f4ebeeb458f72ed02ba29d1053169 Mon Sep 17 00:00:00 2001 From: Marian Beermann Date: Wed, 17 May 2017 20:49:52 +0200 Subject: [PATCH 2/5] rpc negotiate: enable v3 log protocol only for supported clients avoid seeing JSON log output when a 1.1.0b<5 client talks to a 1.1.0b>6 server. --- src/borg/remote.py | 12 ++++++++---- src/borg/testsuite/repository.py | 3 +++ 2 files changed, 11 insertions(+), 4 deletions(-) diff --git a/src/borg/remote.py b/src/borg/remote.py index 3cd4cb938..59d4bf5d1 100644 --- a/src/borg/remote.py +++ b/src/borg/remote.py @@ -313,9 +313,10 @@ class RepositoryServer: # pragma: no cover # clients since 1.1.0b3 use a dict as client_data if isinstance(client_data, dict): self.client_version = client_data[b'client_version'] - level = logging.getLevelName(logging.getLogger('').level) - setup_logging(is_serve=True, json=True, level=level) - logger.debug('Initialized loggin system for new protocol') + if client_data.get(b'client_supports_log_v3', False): + level = logging.getLevelName(logging.getLogger('').level) + setup_logging(is_serve=True, json=True, level=level) + logger.debug('Initialized logging system for new (v3) protocol') else: self.client_version = BORG_VERSION # seems to be newer than current version (no known old format) @@ -559,7 +560,10 @@ class RemoteRepository: try: try: - version = self.call('negotiate', {'client_data': {b'client_version': BORG_VERSION}}) + version = self.call('negotiate', {'client_data': { + b'client_version': BORG_VERSION, + b'client_supports_log_v3': True, + }}) except ConnectionClosed: raise ConnectionClosedWithHint('Is borg working on the server?') from None if version == RPC_PROTOCOL_VERSION: diff --git a/src/borg/testsuite/repository.py b/src/borg/testsuite/repository.py index 192f8d3ea..16f47b915 100644 --- a/src/borg/testsuite/repository.py +++ b/src/borg/testsuite/repository.py @@ -724,6 +724,9 @@ class RemoteRepositoryTestCase(RepositoryTestCase): assert self.repository.borg_cmd(args, testing=False) == ['borg', 'serve', '--umask=077', '--info'] args.remote_path = 'borg-0.28.2' assert self.repository.borg_cmd(args, testing=False) == ['borg-0.28.2', 'serve', '--umask=077', '--info'] + args.debug_topics = ['something_client_side', 'repository_compaction'] + assert self.repository.borg_cmd(args, testing=False) == ['borg-0.28.2', 'serve', '--umask=077', '--info', + '--debug-topic=borg.debug.repository_compaction'] class RemoteLegacyFree(RepositoryTestCaseBase): From 5f4d97ff2ba734a44f46e410a8c60189493afd47 Mon Sep 17 00:00:00 2001 From: Marian Beermann Date: Thu, 18 May 2017 16:54:44 +0200 Subject: [PATCH 3/5] remote: restore "Remote:" prefix (as used in 1.0.x) --- src/borg/remote.py | 18 +++++++++++------- 1 file changed, 11 insertions(+), 7 deletions(-) diff --git a/src/borg/remote.py b/src/borg/remote.py index 59d4bf5d1..3a6373499 100644 --- a/src/borg/remote.py +++ b/src/borg/remote.py @@ -952,28 +952,32 @@ def handle_remote_line(line): assert isinstance(level, int) target_logger = logging.getLogger(msg['name']) # We manually check whether the log message should be propagated + msg['message'] = 'Remote: ' + msg['message'] if level >= target_logger.getEffectiveLevel() and logging.getLogger('borg').json: - sys.stderr.write(line) + sys.stderr.write(json.dumps(msg) + '\n') else: target_logger.log(level, '%s', msg['message']) - elif msg['type'].startswith('progress_') and not msg.get('finished'): + elif msg['type'].startswith('progress_'): # Progress messages are a bit more complex. # First of all, we check whether progress output is enabled. This is signalled # through the effective level of the borg.output.progress logger # (also see ProgressIndicatorBase in borg.helpers). progress_logger = logging.getLogger('borg.output.progress') if progress_logger.getEffectiveLevel() == logging.INFO: - # When progress output is enabled, then we check whether the client is in + # When progress output is enabled, we check whether the client is in # --log-json mode, as signalled by the "json" attribute on the "borg" logger. if logging.getLogger('borg').json: - # In --log-json mode we directly re-emit the progress line as sent by the server. - sys.stderr.write(line) - else: + # In --log-json mode we re-emit the progress JSON line as sent by the server, prefixed + # with "Remote: " when it contains a message. + if 'message' in msg: + msg['message'] = 'Remote: ' + msg['message'] + sys.stderr.write(json.dumps(msg) + '\n') + elif 'message' in msg: # In text log mode we write only the message to stderr and terminate with \r # (carriage return, i.e. move the write cursor back to the beginning of the line) # so that the next message, progress or not, overwrites it. This mirrors the behaviour # of local progress displays. - sys.stderr.write(msg['message'] + '\r') + sys.stderr.write('Remote: ' + msg['message'] + '\r') elif line.startswith('$LOG '): # This format is used by Borg since 1.1.0b1. # It prefixed log lines with $LOG as a marker, followed by the log level From b3b555395cb799f0696c518cb21fb8180e897b52 Mon Sep 17 00:00:00 2001 From: Marian Beermann Date: Sat, 20 May 2017 12:52:32 +0200 Subject: [PATCH 4/5] remote: clarify remote log handling comments --- src/borg/remote.py | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/src/borg/remote.py b/src/borg/remote.py index 3a6373499..5cd95b1c7 100644 --- a/src/borg/remote.py +++ b/src/borg/remote.py @@ -935,7 +935,7 @@ def handle_remote_line(line): """ Handle a remote log line. - This function is remarkably complex because it handles three different wire formats. + This function is remarkably complex because it handles multiple wire formats. """ if line.startswith('{'): # This format is used by Borg since 1.1.0b6 for new-protocol clients. @@ -951,9 +951,9 @@ def handle_remote_line(line): level = getattr(logging, msg['levelname'], logging.CRITICAL) assert isinstance(level, int) target_logger = logging.getLogger(msg['name']) - # We manually check whether the log message should be propagated msg['message'] = 'Remote: ' + msg['message'] - if level >= target_logger.getEffectiveLevel() and logging.getLogger('borg').json: + # In JSON mode, we manually check whether the log message should be propagated. + if logging.getLogger('borg').json and level >= target_logger.getEffectiveLevel(): sys.stderr.write(json.dumps(msg) + '\n') else: target_logger.log(level, '%s', msg['message']) @@ -967,8 +967,8 @@ def handle_remote_line(line): # When progress output is enabled, we check whether the client is in # --log-json mode, as signalled by the "json" attribute on the "borg" logger. if logging.getLogger('borg').json: - # In --log-json mode we re-emit the progress JSON line as sent by the server, prefixed - # with "Remote: " when it contains a message. + # In --log-json mode we re-emit the progress JSON line as sent by the server, + # with the message, if any, prefixed with "Remote: ". if 'message' in msg: msg['message'] = 'Remote: ' + msg['message'] sys.stderr.write(json.dumps(msg) + '\n') @@ -988,6 +988,7 @@ def handle_remote_line(line): # it readable with older (1.0.x) clients. # # TODO: Remove this block (so it'll be handled by the "else:" below) with a Borg 1.1 RC. + # Also check whether client_supports_log_v3 should be removed. _, level, msg = line.split(' ', 2) level = getattr(logging, level, logging.CRITICAL) # str -> int if msg.startswith('Remote:'): From 97e96035318e90f8e6c69ed4fedb76f99de5cb5d Mon Sep 17 00:00:00 2001 From: Marian Beermann Date: Wed, 17 May 2017 17:43:48 +0200 Subject: [PATCH 5/5] implement --debug-topic for remote servers --- src/borg/remote.py | 17 +++++++++++++++++ 1 file changed, 17 insertions(+) diff --git a/src/borg/remote.py b/src/borg/remote.py index 5cd95b1c7..1a67930eb 100644 --- a/src/borg/remote.py +++ b/src/borg/remote.py @@ -654,6 +654,23 @@ This problem will go away as soon as the server has been upgraded to 1.0.7+. opts.append('--critical') else: raise ValueError('log level missing, fix this code') + + # Tell the remote server about debug topics it may need to consider. + # Note that debug topics are usable for "spew" or "trace" logs which would + # be too plentiful to transfer for normal use, so the server doesn't send + # them unless explicitly enabled. + # + # Needless to say, if you do --debug-topic=repository.compaction, for example, + # with a 1.0.x server it won't work, because the server does not recognize the + # option. + # + # This is not considered a problem, since this is a debugging feature that + # should not be used for regular use. + for topic in args.debug_topics: + if '.' not in topic: + topic = 'borg.debug.' + topic + if 'repository' in topic: + opts.append('--debug-topic=%s' % topic) env_vars = [] if not hostname_is_unique(): env_vars.append('BORG_HOSTNAME_IS_UNIQUE=no')