Work around for rsync error 23 (part of #1587) + new "experimental" s…

…napshot log filter (#1621) * Work around for rsync exit code 23: Is no longer an error by adding it to the rsync exit code ignore list (#1587) * Add experimental "rsync transfer failures" filter to snapshot log view * Add links to rsync source code for rsync transfer failure filter * Exclude 'SingletonLock' and 'SingletonCookie' (Discord) and 'lock' (Mozilla Firefox) files by default (part of #1555) * Travis CI config file adjustments since coverage does fail with absolute path to Python for unknown reason (only relative path works) * CI: Remove sudo because travis says so ("no effect anymore") --------- Co-authored-by: aryoda <[email protected]> Co-authored-by: Christian Buhtz <[email protected]>
bit-team · Jan 29, 2024 · dd46462 · dd46462
1 parent 7433583
commit dd46462
Show file tree

Hide file tree

Showing 10 changed files with 150 additions and 21 deletions.
diff --git a/.travis.yml b/.travis.yml
@@ -8,7 +8,6 @@ arch :
  - ppc64le
 
 # ensures that we have UUID filesystem mounts for proper testing
-sudo: true
 dist: focal
 
 addons:
@@ -29,11 +28,15 @@ before_install:
   - sudo apt-get -qq update
   # install screen, and util-linux (provides flock) for test_sshtools
   - sudo apt-get install -y sshfs screen util-linux
+
 jobs:
   exclude:
     - python: "3.9"
     - python: "3.10"
     - python: "3.11"
+    # Excluding this temporarily because of an Issue on Travis. Support contact established.
+    - arch: ppc64le
+      python: "3.12"
 
 install:
   - pip install pylint coveralls pyfakefs
@@ -44,12 +47,20 @@ install:
   - eval `ssh-agent -s`
 
 script:
+  # Is a virtual environment active? Yes: if both variables are not equal.
+  # - python -c "import sys;print(f'{sys.prefix=} {sys.base_prefix=} In virtualenv={sys.prefix != sys.base_prefix}')"
+  # - coverage debug sys
   # compile all files - ensure that syntax is correct
   - python -m compileall common common/test common/plugins qt qt/test qt/plugins
   # run unit tests - ensure that functionality is correct
-  - cd common && ./configure && make unittest-v
+  - cd common
+  - ./configure  --python=python3
+  - make unittest-v
   - cd ..
-  - cd qt && pytest
+  - cd qt
+  - ./configure  --python=python3
+  - make
+  - pytest
 
 after_success:
   - coverage combine

diff --git a/CHANGES b/CHANGES
@@ -1,7 +1,12 @@
 Back In Time
 
 Version 1.4.2-dev (development of upcoming release)
-* Fix bug: `qt5_probing.py` hangs when BiT is run as root and no user is logged into a desktop environment (#1592 and #1580)
+* Feature: Exclude 'SingletonLock' and 'SingletonCookie' (Discord) and 'lock' (Mozilla Firefox) files by default (part of #1555)
+* Work around: Relax `rsync` exit code 23: Ignore instead of error now (part of #1587)
+* Feature (experimental): Add new snapshot log filter `rsync transfer failures (experimental)` to find them easier (they are normally not shown as "error").
+                          This feature is experimental because it is based on hard-coded error message strings in the rsync source code
+                          and may possibly not find all rsync messages or show false positives.
+* Fix bug: 'qt5_probing.py' hangs when BiT is run as root and no user is logged into a desktop environment (#1592 and #1580)
 * Fix bug: Launching BiT GUI (root) hangs on Wayland without showing the GUI (#836)
 * Improve: Launcher for BiT GUI (root) does not enforce Wayland anymore but uses same settings as for BiT GUI (userland) (#1350)
 * Fix bug: Disabling suspend during taking a backup ("inhibit suspend") hangs when BiT is run as root and no user is logged into a desktop environment (#1592)
@@ -77,7 +82,7 @@ Version 1.3.3 (2023-01-04)
 * Desktop integration: Update .desktop file to mark Back In Time as a single main window program (#1258)
 * Feature: Write all log output to stderr; do not pollute stdout with INFO and WARNING messages anymore (#1337)
 * Fix bug: RTE "reentrant call inside io.BufferedWriter" in logFile.flush() during backup (#1003)
-* Fix bug: Incompatibility with rsync 3.2.4 or later because of rsync's "new argument protection" (#1247). Deactivate "--old-args" rsync argument earlier recommaned to users as a workaround.
+* Fix bug: Incompatibility with rsync 3.2.4 or later because of rsync's "new argument protection" (#1247). Deactivate "--old-args" rsync argument earlier recommanded to users as a workaround.
 * Fix bug: DeprecationWarnings about invalid escape sequences.
 * Fix bug: AttributeError in "Diff Options" dialog (#898)
 * Fix bug: Settings GUI: "Save password to Keyring" was disabled due to "no appropriate keyring found" (#1321)

diff --git a/common/config.py b/common/config.py
@@ -116,6 +116,13 @@ class Config(configfile.ConfigFileWithProfiles):
         '/var/backups/*',
         '.Private',
         '/swapfile',
+        # Discord files
+        # See also: https://github.com/bit-team/backintime/issues/1555#issuecomment-1787230708
+        'SingletonLock',
+        'SingletonCookie',
+        # Mozilla files
+        # See also: https://github.com/bit-team/backintime/issues/1555#issuecomment-1787111063
+        'lock'
     ]
 
     DEFAULT_RUN_NICE_FROM_CRON = True

diff --git a/common/configure b/common/configure
@@ -10,7 +10,7 @@ MAKEFILE="$(mktemp)"
 UNINSTALL_FILES="$(mktemp)"
 UNINSTALL_DIRS="$(mktemp)"
 
-#set default options
+# set default options
 PYTHON="/usr/bin/python3"
 
 USR_BIN_FILES="backintime backintime-askpass"
@@ -281,9 +281,9 @@ for i in "pytest" "py.test-3" "py.test-3.6" "py.test-3.5" "py.test-3.4"; do
     fi
 done
 COVERAGE=$(which coverage 2>/dev/null)
-#use "coverage run" only on travis-ci.org and if it is available
-#this will pass information to coveralls.io.
-#otherwise use "python", "python3" or if available "py.test-3"
+# Use "coverage run" only on travis-ci.org and if it is available
+# this will pass information to coveralls.io.
+# Otherwise use "python", "python3" or if available "py.test-3"
 if onTravis && [ -n "${COVERAGE}" ]; then
     CMD="coverage run -p"
 else

diff --git a/common/qt5_probing.py b/common/qt5_probing.py
@@ -5,6 +5,8 @@
 
 logger.openlog()
 
+# from tools import isRoot
+
 # This mini python script is used to determine if a Qt5 GUI application
 # can be created without an error.
 #
@@ -90,6 +92,15 @@
     logger.debug(f"XAUTHORITY={os.environ.get('XAUTHORITY', '($XAUTHORITY is not set)')}")
     logger.debug(f"QT_QPA_PLATFORM={os.environ.get('QT_QPA_PLATFORM', '($QT_QPA_PLATFORM is not set)')}")
 
+    logger.debug(f"Current euid: {os.geteuid()}")
+    # Jan 25, 2024 Not enabled but just documented here since this "fix" is a hack (assumes hard-coded UID 1000 to be always correct). But it works in 99 % of installations
+    # if isRoot():
+    #     logger.debug("Changing euid from root to user as work-around for #1592 (qt5_probing hangs in root cron job)")
+    #     # Fix inspired by
+    #     # https://stackoverflow.com/questions/71425861/connecting-to-user-dbus-as-root
+    #     os.seteuid(1000)
+    #     logger.debug(f"New euid: {os.geteuid()}")
+
     from PyQt5 import QtCore
     from PyQt5.QtWidgets import QApplication
 

diff --git a/common/snapshotlog.py b/common/snapshotlog.py
@@ -38,18 +38,72 @@ class LogFilter(object):
                                     :py:data:`ERROR_AND_CHANGES`
         decode (encfstools.Decode): instance used for decoding lines or ``None``
     """
+
+    # TODO Better use an enumeration
     NO_FILTER =         0
     ERROR =             1
     CHANGES =           2
     INFORMATION =       3
     ERROR_AND_CHANGES = 4
+    RSYNC_TRANSFER_FAILURES = 5
 
+    # Regular expressions used for filtering log file lines.
+    # RegExp syntax see: https://docs.python.org/3.10/library/re.html#regular-expression-syntax
+    # (?:...) = the matched substring cannot be retrieved in a group (non-capturing)
     REGEX = {None:              None,
              NO_FILTER:         None,
              ERROR:             re.compile(r'^(?:\[E\]|[^\[])'),
              CHANGES:           re.compile(r'^(?:\[C\]|[^\[])'),
              INFORMATION:       re.compile(r'^(?:\[I\]|[^\[])'),
-             ERROR_AND_CHANGES: re.compile(r'^(?:\[E\]|\[C\]|[^\[])')}
+             ERROR_AND_CHANGES: re.compile(r'^(?:\[E\]|\[C\]|[^\[])'),
+             RSYNC_TRANSFER_FAILURES: re.compile(
+                 # All links to rsync's source reference the commit 2f9b963 from Jun 27, 2023 (most-recent commit on "master" as at Jan 28, 2024)
+                 r'.*(?:'
+                 r'Invalid cross-device link'     # not directly contained in rsync's source code but may be catched and passed through as-is
+                 r'|symlink has no referent'      # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/flist.c#L1281
+                 r'|readlink_stat\(.?\) failed'   # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/flist.c#L1294
+                 r'|link_stat .* failed'          # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/flist.c#L1810
+                 r'|receive_sums failed'          # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/sender.c#L347
+                 r'|send_files failed to open'    # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/sender.c#L361
+                 r'|fstat failed'                 # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/sender.c#L373
+                 r'|read errors mapping'          # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/sender.c#L435
+                 r'|change_dir .* failed'         # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/main.c#L749
+                                                  # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/main.c#L807
+                                                  # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/main.c#L827
+                                                  # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/main.c#L1161
+                 r'|skipping overly long name'    # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/flist.c#L1247
+                 r'|skipping file with bogus \(zero\) st_mode'  # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/flist.c#L1300
+                 r'|skipping symlink with 0-length value'       # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/flist.c#L1569
+                 r'|cannot convert filename'      # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/flist.c#L748
+                                                  # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/flist.c#L1599
+                 r'|cannot convert symlink data for'  # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/flist.c#L1144
+                                                      # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/flist.c#L1613
+                 r'|opendir .* failed'            # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/flist.c#L1842
+                 r'|filename overflows max-path len by'   # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/flist.c#L1868
+                 r'|cannot send file with empty name in'  # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/flist.c#L1876
+                 r'|readdir\(.*\)'                        # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/flist.c#L1888
+                 r'|cannot add local filter rules in long-named directory'  # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/exclude.c#L817
+                 r'|failed to re-read xattr'                                # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/xattrs.c#L662
+                 r'|Skipping sender remove of destination file'     # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/sender.c#L152
+                 r'|Skipping sender remove for changed file'        # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/sender.c#L161
+                 r'|could not make way for'                         # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/delete.c#L220
+                 r'|system says the ACL I packed is invalid'        # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/acls.c#L435
+                 r'|recv_acl_access: value out of range'            # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/acls.c#L689
+                 r'|recv_acl_index: .* ACL index'                   # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/acls.c#L739
+                 r'|Create time value of .* truncated on receiver'  # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/flist.c#L858
+                 r'|FATAL I/O ERROR: dying to avoid a \-\-delete'   # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/flist.c#L2005
+                 r'|IO error encountered'                           # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/generator.c#L295
+                 r'|some files/attrs were not transferred'  # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/log.c#L97
+                 r'|temporary filename too long'            # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/receiver.c#L138
+                 r'|No batched update for'                  # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/receiver.c#L456
+                 r'|recv_files: .* is a directory'          # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/receiver.c#L805
+                 r'|no ftruncate for over-long pre-alloc'   # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/util1.c#L438
+                 r'|daemon refused to receive'              # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/generator.c#L1270
+                 r'|get_xattr_data: lgetxattr'              # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/xattrs.c#L199
+                                                            # https://github.com/WayneD/rsync/blob/2f9b963abaa52e44891180fe6c0d1c2219f6686d/xattrs.c#L215
+                 # r').*'  # no need to match the remainder of the line
+                 r')'
+             )}
 
     def __init__(self, mode = 0, decode = None):
         self.regex = self.REGEX[mode]

diff --git a/common/snapshots.py b/common/snapshots.py
@@ -617,7 +617,7 @@ def remove(self, sid):
         Remove snapshot ``sid``.
 
         BUHTZ 2022-10-11: From my understanding rsync is used here to sync the
-        directory of a concrete snapshot (``sid```) against an empty temporary
+        directory of a concrete snapshot (``sid``) against an empty temporary
         directory. In the consequence the sid directory is empty but not
         deleted.
         To delete that directory simple `rm` call (via `shutil` package) is
@@ -1252,6 +1252,7 @@ def takeSnapshot(self, sid, now, include_folders):
         # (not as ERROR). The values are message strings for the snapshot log.
         rsync_non_error_exit_codes = {
             0: _("Success"),
+            23: _("Partial transfer due to error"),  # ignored as fix for #1587 (until we introduce a new snapshot result category "(with warnings)")
             24: _("Partial transfer due to vanished source files (see 'man rsync')")
         }
 
@@ -1261,11 +1262,11 @@ def takeSnapshot(self, sid, now, include_folders):
             self.setTakeSnapshotMessage(0,
                                         rsync_exit_code_msg + ": {msg}".format(
                                             msg=rsync_non_error_exit_codes[rsync_exit_code]))
-        elif rsync_exit_code > 0:  # indicates a rsync error
+        elif rsync_exit_code > 0:  # indicates an rsync error
             params[0] = True  # HACK to fix #489 (params[0] and has_errors should be merged)
             self.setTakeSnapshotMessage(1,
                                         rsync_exit_code_msg + ": " + _("See 'man rsync' for more details"))
-        elif rsync_exit_code < 0:  # indicates a rsync error caused by a signal
+        elif rsync_exit_code < 0:  # indicates an rsync error caused by a signal
             params[0] = True  # HACK to fix #489 (params[0] and has_errors should be merged)
             self.setTakeSnapshotMessage(1,
                                         rsync_exit_code_msg + ": " + _("Negative rsync exit codes are signal numbers, see 'kill -l' and 'man kill'"))
@@ -2625,7 +2626,8 @@ def fileInfo(self, d):
         except PermissionError as e:
             logger.error('Failed to write {}: {}'.format(self.FILEINFO, str(e)))
 
-    #TODO: use @property decorator
+    # TODO use @property decorator? IMHO not because it is not a "getter" but processes data
+    # TODO Should have an action name like "loadLogFile"
     def log(self, mode = None, decode = None):
         """
         Load log from "takesnapshot.log.bz2"

diff --git a/common/test/test_snapshotlog.py b/common/test/test_snapshotlog.py
@@ -73,6 +73,22 @@ def test_filter(self):
         for line in (self.i,):
             self.assertIsNone(logFilter.filter(line))
 
+        # New filter (#1587): rsync transfer failures (experimental)
+        logFilter = snapshotlog.LogFilter(mode=snapshotlog.LogFilter.RSYNC_TRANSFER_FAILURES)
+        log_lines = (
+            '[I] Take snapshot (rsync: symlink has no referent: "/home/user/Documents/dead-link")',
+            '[E] Error: rsync: [sender] send_files failed to open "/home/user/Documents/root_only_file.txt": Permission denied (13)',
+            '[I] Schnappschuss erstellen (rsync: IO error encountered -- skipping file deletion)',
+            '[I] Schnappschuss erstellen (rsync: rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1333) [sender=3.2.3])',
+            '[I] Take snapshot (rsync: rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1333) [sender=3.2.3])',
+        )
+        for line in log_lines:
+            self.assertEqual(line, logFilter.filter(line))
+        for line in (self.e, self.c, self.i, self.h):
+            self.assertIsNone(logFilter.filter(line))
+        for line in (self.n):
+            self.assertEqual(line, logFilter.filter(line))  # empty line stays empty line
+
 class TestSnapshotLog(generic.SnapshotsTestCase):
     def setUp(self):
         super(TestSnapshotLog, self).setUp()

diff --git a/qt/app.py b/qt/app.py
@@ -1165,7 +1165,7 @@ def btnNameSnapshotClicked(self):
 
     def btnLastLogViewClicked (self):
         with self.suspendMouseButtonNavigation():
-            logviewdialog.LogViewDialog(self).show()
+            logviewdialog.LogViewDialog(self).show()  # no SID argument in constructor means "show last log"
 
     def btnSnapshotLogViewClicked (self):
         item = self.timeLine.currentItem()