Work around for rsync exit code 23: No longer an error (bit-team#1587)(

* rsync exit code 23 is now in the ignore list
* Add experimental "rsync transfer failures" filter to snapshot log view
* Exclude 'SingletonLock' and 'SingletonCookie' (Discord) and 'lock' (Mozilla Firefox) files by default (part of bit-team#1555)

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)

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

common/snapshotlog.py

@@ -38,18 +38,65 @@ 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(
+                 r'.*(?:'
+                 r'Invalid cross-device link'
+                 r'|symlink has no referent'
+                 r'|readlink_stat\(.?\) failed'
+                 r'|link_stat .* failed'
+                 r'|receive_sums failed'
+                 r'|send_files failed to open'
+                 r'|fstat failed'
+                 r'|read errors mapping'
+                 r'|change_dir .* failed'
+                 r'|skipping overly long name'
+                 r'|skipping file with bogus \(zero\) st_mode'
+                 r'|skipping symlink with 0-length value'
+                 r'|cannot convert filename'
+                 r'|cannot convert symlink data for'
+                 r'|opendir .* failed'
+                 r'|filename overflows max-path len by'
+                 r'|cannot send file with empty name in'
+                 r'|readdir\(.*\)'
+                 r'|cannot add local filter rules in long-named directory'
+                 r'|failed to re-read xattr'
+                 r'|Skipping sender remove of destination file'
+                 r'|Skipping sender remove for changed file'
+                 r'|could not make way for'
+                 r'|system says the ACL I packed is invalid'
+                 r'|recv_acl_access: value out of range'
+                 r'|recv_acl_index: .* ACL index'
+                 r'|Create time value of .* truncated on receiver'
+                 r'|FATAL I/O ERROR: dying to avoid a \-\-delete'
+                 r'|IO error encountered'  # TODO reported in an issue but is this string really contained in the rsync source code?
+                 r'|some files/attrs were not transferred'  # TODO reported in an issue but is this string really contained in the rsync source code?
+                 r'|temporary filename too long'
+                 r'|No batched update for'
+                 r'|recv_files: .* is a directory'
+                 r'|no ftruncate for over-long pre-alloc'
+                 r'|daemon refused to receive'
+                 r'|get_xattr_data: lgetxattr'
+                 # r').*'  # no need to match the remainder of the line
+                 r')'
+             )}
 
     def __init__(self, mode = 0, decode = None):
         self.regex = self.REGEX[mode]

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"

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()

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()

qt/logviewdialog.py

@@ -30,6 +30,15 @@
 
 class LogViewDialog(QDialog):
     def __init__(self, parent, sid = None, systray = False):
+        """
+        Instantiate a snapshot log file viewer
+
+        Args:
+            parent:
+            sid (:py:class:`SID`): snapshot ID whose log file shall be shown
+                                   (``None`` = show last log)
+            systray (bool): TODO Show log from systray icon or from App (boolean)
+        """
         if systray:
             super(LogViewDialog, self).__init__()
         else:
@@ -88,17 +97,18 @@ def __init__(self, parent, sid = None, systray = False):
         layout.addWidget(self.comboFilter, 1)
         self.comboFilter.currentIndexChanged.connect(self.comboFilterChanged)
 
-        self.comboFilter.addItem(_('All'), 0)
+        self.comboFilter.addItem(_('All'), snapshotlog.LogFilter.NO_FILTER)
 
         # Note about ngettext plural forms: n=102 means "Other" in Arabic and
         # "Few" in Polish.
         # Research in translation community indicate this as the best fit to
         # the meaning of "all".
-        self.comboFilter.addItem(' + '.join((_('Errors'), _('Changes'))), 4)
+        self.comboFilter.addItem(' + '.join((_('Errors'), _('Changes'))), snapshotlog.LogFilter.ERROR_AND_CHANGES)
         self.comboFilter.setCurrentIndex(self.comboFilter.count() - 1)
-        self.comboFilter.addItem(_('Errors'), 1)
-        self.comboFilter.addItem(_('Changes'), 2)
-        self.comboFilter.addItem(_('Information'), 3)
+        self.comboFilter.addItem(_('Errors'), snapshotlog.LogFilter.ERROR)
+        self.comboFilter.addItem(_('Changes'), snapshotlog.LogFilter.CHANGES)
+        self.comboFilter.addItem(_('Information'), snapshotlog.LogFilter.INFORMATION)
+        self.comboFilter.addItem(_('rsync transfer failures (experimental)'), snapshotlog.LogFilter.RSYNC_TRANSFER_FAILURES)
 
         # text view
         self.txtLogView = QPlainTextEdit(self)
@@ -130,7 +140,7 @@ def __init__(self, parent, sid = None, systray = False):
             # only watch if we show the last log
             log = self.config.takeSnapshotLogFile(self.comboProfiles.currentProfileID())
             self.watcher.addPath(log)
-        self.watcher.fileChanged.connect(self.updateLog)
+        self.watcher.fileChanged.connect(self.updateLog)  # passes the path to the changed file to updateLog()
 
         self.txtLogView.setContextMenuPolicy(Qt.CustomContextMenu)
         self.txtLogView.customContextMenuRequested.connect(self.contextMenuClicked)
@@ -252,11 +262,24 @@ def updateDecode(self):
                 self.cbDecode.setChecked(False)
 
     def updateLog(self, watchPath = None):
+        """
+        Show the log file of the current snapshot in the GUI
+
+        Args:
+            watchPath: FQN to a log file (as string) whose changes are watched
+                       via ``QFileSystemWatcher``. In case of changes
+                       this function is called with the log file
+                       and only the new lines in the log file are appended
+                       to the log file widget in the GUI
+                       Use ``None`` if a complete log file shall be shown
+                       at once.
+        """
         if not self.enableUpdate:
             return
 
         mode = self.comboFilter.itemData(self.comboFilter.currentIndex())
 
+        # TODO This expressions is hard to understand (watchPath is not a boolean!)
         if watchPath and self.sid is None:
             # remove path from watch to prevent multiple updates at the same time
             self.watcher.removePath(watchPath)