From a0c8c40f27110f906ef64c02282a7ab045e694a6 Mon Sep 17 00:00:00 2001 From: Thomas Waldmann Date: Sat, 20 Aug 2016 17:23:02 +0200 Subject: [PATCH 1/2] improve error logging, fixes #1440 archiver: split traceback and msg, have separate log level for traceback, log LockTimeout at debug level, for "Error" exceptions: always log the traceback, either at ERROR or DEBUG level. remote: if we have an "Error" typed exception instance, we can use its traceback flag and .get_message() as we do locally. --- src/borg/archiver.py | 32 +++++++++++++++++++++++--------- src/borg/remote.py | 22 ++++++++++++++++------ 2 files changed, 39 insertions(+), 15 deletions(-) diff --git a/src/borg/archiver.py b/src/borg/archiver.py index e8e1568f1..cb12309fb 100644 --- a/src/borg/archiver.py +++ b/src/borg/archiver.py @@ -2354,37 +2354,51 @@ def main(): # pragma: no cover sys.stderr = ErrorIgnoringTextIOWrapper(sys.stderr.buffer, sys.stderr.encoding, 'replace', line_buffering=True) setup_signal_handlers() archiver = Archiver() - msg = None + msg = tb = None + tb_log_level = logging.ERROR try: args = archiver.get_args(sys.argv, os.environ.get('SSH_ORIGINAL_COMMAND')) except Error as e: msg = e.get_message() - if e.traceback: - msg += "\n%s\n%s" % (traceback.format_exc(), sysinfo()) + tb_log_level = logging.ERROR if e.traceback else logging.DEBUG + tb = '%s\n%s' % (traceback.format_exc(), sysinfo()) # we might not have logging setup yet, so get out quickly print(msg, file=sys.stderr) + if tb_log_level == logging.ERROR: + print(tb, file=sys.stderr) sys.exit(e.exit_code) try: exit_code = archiver.run(args) except Error as e: msg = e.get_message() - if e.traceback: - msg += "\n%s\n%s" % (traceback.format_exc(), sysinfo()) + tb_log_level = logging.ERROR if e.traceback else logging.DEBUG + tb = "%s\n%s" % (traceback.format_exc(), sysinfo()) exit_code = e.exit_code except RemoteRepository.RPCError as e: - msg = '%s\n%s' % (str(e), sysinfo()) + msg = "%s %s" % (e.remote_type, e.name) + important = e.remote_type not in ('LockTimeout', ) + tb_log_level = logging.ERROR if important else logging.DEBUG + tb = sysinfo() exit_code = EXIT_ERROR except Exception: - msg = 'Local Exception.\n%s\n%s' % (traceback.format_exc(), sysinfo()) + msg = 'Local Exception' + tb_log_level = logging.ERROR + tb = '%s\n%s' % (traceback.format_exc(), sysinfo()) exit_code = EXIT_ERROR except KeyboardInterrupt: - msg = 'Keyboard interrupt.\n%s\n%s' % (traceback.format_exc(), sysinfo()) + msg = 'Keyboard interrupt' + tb_log_level = logging.DEBUG + tb = '%s\n%s' % (traceback.format_exc(), sysinfo()) exit_code = EXIT_ERROR except SIGTERMReceived: - msg = 'Received SIGTERM.' + msg = 'Received SIGTERM' + tb_log_level = logging.DEBUG + tb = '%s\n%s' % (traceback.format_exc(), sysinfo()) exit_code = EXIT_ERROR if msg: logger.error(msg) + if traceback: + logger.log(tb_log_level, tb) if args.show_rc: rc_logger = logging.getLogger('borg.output.show-rc') exit_msg = 'terminating with %s status, rc %d' diff --git a/src/borg/remote.py b/src/borg/remote.py index 18637cae7..b0a319462 100644 --- a/src/borg/remote.py +++ b/src/borg/remote.py @@ -6,6 +6,7 @@ import select import shlex import sys import tempfile +import traceback from subprocess import Popen, PIPE import msgpack @@ -101,12 +102,21 @@ class RepositoryServer: # pragma: no cover f = getattr(self.repository, method) res = f(*args) except BaseException as e: - # These exceptions are reconstructed on the client end in RemoteRepository.call_many(), - # and will be handled just like locally raised exceptions. Suppress the remote traceback - # for these, except ErrorWithTraceback, which should always display a traceback. - if not isinstance(e, (Repository.DoesNotExist, Repository.AlreadyExists, PathNotAllowed)): - logging.exception('Borg %s: exception in RPC call:', __version__) - logging.error(sysinfo()) + if isinstance(e, (Repository.DoesNotExist, Repository.AlreadyExists, PathNotAllowed)): + # These exceptions are reconstructed on the client end in RemoteRepository.call_many(), + # and will be handled just like locally raised exceptions. Suppress the remote traceback + # for these, except ErrorWithTraceback, which should always display a traceback. + pass + else: + if isinstance(e, Error): + tb_log_level = logging.ERROR if e.traceback else logging.DEBUG + msg = e.get_message() + else: + tb_log_level = logging.ERROR + msg = '%s Exception in RPC call' % e.__class__.__name__ + tb = '%s\n%s' % (traceback.format_exc(), sysinfo()) + logging.error(msg) + logging.log(tb_log_level, tb) exc = "Remote Exception (see remote log for the traceback)" os.write(stdout_fd, msgpack.packb((1, msgid, e.__class__.__name__, exc))) else: From 41e4707d6a4d0437d6610cfb3151ae80adb0390b Mon Sep 17 00:00:00 2001 From: Thomas Waldmann Date: Sat, 20 Aug 2016 23:09:42 +0200 Subject: [PATCH 2/2] fixup: meant "tb", not "traceback" --- src/borg/archiver.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/borg/archiver.py b/src/borg/archiver.py index cb12309fb..0db6963a5 100644 --- a/src/borg/archiver.py +++ b/src/borg/archiver.py @@ -2397,7 +2397,7 @@ def main(): # pragma: no cover exit_code = EXIT_ERROR if msg: logger.error(msg) - if traceback: + if tb: logger.log(tb_log_level, tb) if args.show_rc: rc_logger = logging.getLogger('borg.output.show-rc')