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.

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: