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.
This commit is contained in:
Thomas Waldmann 2016-08-20 17:23:02 +02:00
parent 45fd66f6e1
commit a0c8c40f27
2 changed files with 39 additions and 15 deletions

View File

@ -2354,37 +2354,51 @@ def main(): # pragma: no cover
sys.stderr = ErrorIgnoringTextIOWrapper(sys.stderr.buffer, sys.stderr.encoding, 'replace', line_buffering=True) sys.stderr = ErrorIgnoringTextIOWrapper(sys.stderr.buffer, sys.stderr.encoding, 'replace', line_buffering=True)
setup_signal_handlers() setup_signal_handlers()
archiver = Archiver() archiver = Archiver()
msg = None msg = tb = None
tb_log_level = logging.ERROR
try: try:
args = archiver.get_args(sys.argv, os.environ.get('SSH_ORIGINAL_COMMAND')) args = archiver.get_args(sys.argv, os.environ.get('SSH_ORIGINAL_COMMAND'))
except Error as e: except Error as e:
msg = e.get_message() msg = e.get_message()
if e.traceback: tb_log_level = logging.ERROR if e.traceback else logging.DEBUG
msg += "\n%s\n%s" % (traceback.format_exc(), sysinfo()) tb = '%s\n%s' % (traceback.format_exc(), sysinfo())
# we might not have logging setup yet, so get out quickly # we might not have logging setup yet, so get out quickly
print(msg, file=sys.stderr) print(msg, file=sys.stderr)
if tb_log_level == logging.ERROR:
print(tb, file=sys.stderr)
sys.exit(e.exit_code) sys.exit(e.exit_code)
try: try:
exit_code = archiver.run(args) exit_code = archiver.run(args)
except Error as e: except Error as e:
msg = e.get_message() msg = e.get_message()
if e.traceback: tb_log_level = logging.ERROR if e.traceback else logging.DEBUG
msg += "\n%s\n%s" % (traceback.format_exc(), sysinfo()) tb = "%s\n%s" % (traceback.format_exc(), sysinfo())
exit_code = e.exit_code exit_code = e.exit_code
except RemoteRepository.RPCError as e: 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 exit_code = EXIT_ERROR
except Exception: 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 exit_code = EXIT_ERROR
except KeyboardInterrupt: 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 exit_code = EXIT_ERROR
except SIGTERMReceived: 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 exit_code = EXIT_ERROR
if msg: if msg:
logger.error(msg) logger.error(msg)
if traceback:
logger.log(tb_log_level, tb)
if args.show_rc: if args.show_rc:
rc_logger = logging.getLogger('borg.output.show-rc') rc_logger = logging.getLogger('borg.output.show-rc')
exit_msg = 'terminating with %s status, rc %d' exit_msg = 'terminating with %s status, rc %d'

View File

@ -6,6 +6,7 @@ import select
import shlex import shlex
import sys import sys
import tempfile import tempfile
import traceback
from subprocess import Popen, PIPE from subprocess import Popen, PIPE
import msgpack import msgpack
@ -101,12 +102,21 @@ class RepositoryServer: # pragma: no cover
f = getattr(self.repository, method) f = getattr(self.repository, method)
res = f(*args) res = f(*args)
except BaseException as e: except BaseException as e:
# These exceptions are reconstructed on the client end in RemoteRepository.call_many(), if isinstance(e, (Repository.DoesNotExist, Repository.AlreadyExists, PathNotAllowed)):
# and will be handled just like locally raised exceptions. Suppress the remote traceback # These exceptions are reconstructed on the client end in RemoteRepository.call_many(),
# for these, except ErrorWithTraceback, which should always display a traceback. # and will be handled just like locally raised exceptions. Suppress the remote traceback
if not isinstance(e, (Repository.DoesNotExist, Repository.AlreadyExists, PathNotAllowed)): # for these, except ErrorWithTraceback, which should always display a traceback.
logging.exception('Borg %s: exception in RPC call:', __version__) pass
logging.error(sysinfo()) 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)" exc = "Remote Exception (see remote log for the traceback)"
os.write(stdout_fd, msgpack.packb((1, msgid, e.__class__.__name__, exc))) os.write(stdout_fd, msgpack.packb((1, msgid, e.__class__.__name__, exc)))
else: else: