rdiff-backup crashes when running backup

[Walt Mankowski]

Here's the output from last night's cronjob:

Subject: Cron <root@scruffy> if [ -x /backup/scruffy ]; then rdiff-backup --print-statistics --exclude-filelist /usr/local/etc/rdiff_exclude / /backup/scruffy; fi

UpdateError: 'home/waltman/.cache/keybase/keybase.service.log' Updated mirror temp file '/backup/scruffy/home/waltman/.cache/keybase/rdiff-backup.tmp.15973' does not
match source
UpdateError: 'home/waltman/.irssi/db/messages.sqlite' Updated mirror temp file '/backup/scruffy/home/waltman/.irssi/db/rdiff-backup.tmp.56956' does not match source
UpdateError: 'run/rpc_pipefs/gssd/clntXX/info' Updated mirror temp file '/backup/scruffy/run/rpc_pipefs/gssd/clntXX/rdiff-backup.tmp.84241' does not match source
UpdateError: 'run/snapd/ns/discord.mnt' [Errno 22] Invalid argument
UpdateError: 'run/snapd/ns/lxd.mnt' [Errno 22] Invalid argument
Exception 'sequence item 0: expected str instance, bytes found' raised of class '<class 'TypeError'>':
  File "/usr/lib/python3/dist-packages/rdiff_backup/Main.py", line 390, in error_check_Main
    Main(arglist)
  File "/usr/lib/python3/dist-packages/rdiff_backup/Main.py", line 412, in Main
    take_action(rps)
  File "/usr/lib/python3/dist-packages/rdiff_backup/Main.py", line 348, in take_action
    Backup(rps[0], rps[1])
  File "/usr/lib/python3/dist-packages/rdiff_backup/Main.py", line 434, in Backup
    backup.Mirror_and_increment(rpin, rpout, incdir)
  File "/usr/lib/python3/dist-packages/rdiff_backup/backup.py", line 55, in Mirror_and_increment
    DestS.patch_and_increment(dest_rpath, source_diffiter, inc_rpath)
  File "/usr/lib/python3/dist-packages/rdiff_backup/backup.py", line 279, in patch_and_increment
    for diff in rorpiter.FillInIter(source_diffiter, dest_rpath):
  File "/usr/lib/python3/dist-packages/rdiff_backup/rorpiter.py", line 202, in FillInIter
    for rp in rpiter:
  File "/usr/lib/python3/dist-packages/rdiff_backup/backup.py", line 114, in get_diffs
    for dest_sig in dest_sigiter:
  File "/usr/lib/python3/dist-packages/rdiff_backup/backup.py", line 196, in get_sigs
    for src_rorp, dest_rorp in cls.CCPP:
  File "/usr/lib/python3/dist-packages/rdiff_backup/backup.py", line 361, in __next__
    source_rorp, dest_rorp = next(self.iter)
  File "/usr/lib/python3/dist-packages/rdiff_backup/rorpiter.py", line 95, in Collate2Iters
    relem1 = next(riter1)
  File "/usr/lib/python3/dist-packages/rdiff_backup/rorpiter.py", line 376, in __next__
    next_elem = next(self.iter)
  File "/usr/lib/python3/dist-packages/rdiff_backup/selection.py", line 138, in Iterate_fast
    rpath, val = next(diryield_stack[-1])
  File "/usr/lib/python3/dist-packages/rdiff_backup/selection.py", line 121, in diryield
    new_rpath = robust.check_common_error(
  File "/usr/lib/python3/dist-packages/rdiff_backup/robust.py", line 44, in check_common_error
    return error_handler(exc, *args)
  File "/usr/lib/python3/dist-packages/rdiff_backup/selection.py", line 108, in error_handler
    log.ErrorLog.write_if_open("ListError", rpath.index + (filename, ),
  File "/usr/lib/python3/dist-packages/rdiff_backup/log.py", line 313, in write_if_open
    cls.write(error_type, rp, exc)
  File "/usr/lib/python3/dist-packages/rdiff_backup/log.py", line 284, in write
    logstr = cls.get_log_string(error_type, rp, exc)
  File "/usr/lib/python3/dist-packages/rdiff_backup/log.py", line 322, in get_log_string
    return "%s: '%s' %s" % (error_type, cls.get_indexpath(rp), exc)
  File "/usr/lib/python3/dist-packages/rdiff_backup/log.py", line 302, in get_indexpath
    return "/".join(obj)

Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/rdiff_backup/robust.py", line 35, in check_common_error
    return function(*args)
  File "/usr/lib/python3/dist-packages/rdiff_backup/rpath.py", line 1410, in append
    return self.__class__(self.conn, self.base, self.index + ext)
  File "/usr/lib/python3/dist-packages/rdiff_backup/rpath.py", line 1082, in __init__
    self.setdata()
  File "/usr/lib/python3/dist-packages/rdiff_backup/rpath.py", line 1108, in setdata
    self.data = self.conn.rpath.make_file_dict(self.path)
  File "/usr/lib/python3/dist-packages/rdiff_backup/rpath.py", line 386, in make_file_dict
    statblock = os.lstat(filename)
PermissionError: [Errno 13] Permission denied: b'/run/user/1000/doc'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/rdiff_backup/log.py", line 299, in get_indexpath
    return obj.get_safeindexpath()
AttributeError: 'tuple' object has no attribute 'get_safeindexpath'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/bin/rdiff-backup", line 32, in <module>
    rdiff_backup.Main.error_check_Main(sys.argv[1:])
  File "/usr/lib/python3/dist-packages/rdiff_backup/Main.py", line 390, in error_check_Main
    Main(arglist)
  File "/usr/lib/python3/dist-packages/rdiff_backup/Main.py", line 412, in Main
    take_action(rps)
  File "/usr/lib/python3/dist-packages/rdiff_backup/Main.py", line 348, in take_action
    Backup(rps[0], rps[1])
  File "/usr/lib/python3/dist-packages/rdiff_backup/Main.py", line 434, in Backup
    backup.Mirror_and_increment(rpin, rpout, incdir)
  File "/usr/lib/python3/dist-packages/rdiff_backup/backup.py", line 55, in Mirror_and_increment
    DestS.patch_and_increment(dest_rpath, source_diffiter, inc_rpath)
  File "/usr/lib/python3/dist-packages/rdiff_backup/backup.py", line 279, in patch_and_increment
    for diff in rorpiter.FillInIter(source_diffiter, dest_rpath):
  File "/usr/lib/python3/dist-packages/rdiff_backup/rorpiter.py", line 202, in FillInIter
    for rp in rpiter:
  File "/usr/lib/python3/dist-packages/rdiff_backup/backup.py", line 114, in get_diffs
    for dest_sig in dest_sigiter:
  File "/usr/lib/python3/dist-packages/rdiff_backup/backup.py", line 196, in get_sigs
    for src_rorp, dest_rorp in cls.CCPP:
  File "/usr/lib/python3/dist-packages/rdiff_backup/backup.py", line 361, in __next__
    source_rorp, dest_rorp = next(self.iter)
  File "/usr/lib/python3/dist-packages/rdiff_backup/rorpiter.py", line 95, in Collate2Iters
    relem1 = next(riter1)
  File "/usr/lib/python3/dist-packages/rdiff_backup/rorpiter.py", line 376, in __next__
    next_elem = next(self.iter)
  File "/usr/lib/python3/dist-packages/rdiff_backup/selection.py", line 138, in Iterate_fast
    rpath, val = next(diryield_stack[-1])
  File "/usr/lib/python3/dist-packages/rdiff_backup/selection.py", line 121, in diryield
    new_rpath = robust.check_common_error(
  File "/usr/lib/python3/dist-packages/rdiff_backup/robust.py", line 44, in check_common_error
    return error_handler(exc, *args)
  File "/usr/lib/python3/dist-packages/rdiff_backup/selection.py", line 108, in error_handler
    log.ErrorLog.write_if_open("ListError", rpath.index + (filename, ),
  File "/usr/lib/python3/dist-packages/rdiff_backup/log.py", line 313, in write_if_open
    cls.write(error_type, rp, exc)
  File "/usr/lib/python3/dist-packages/rdiff_backup/log.py", line 284, in write
    logstr = cls.get_log_string(error_type, rp, exc)
  File "/usr/lib/python3/dist-packages/rdiff_backup/log.py", line 322, in get_log_string
    return "%s: '%s' %s" % (error_type, cls.get_indexpath(rp), exc)
  File "/usr/lib/python3/dist-packages/rdiff_backup/log.py", line 302, in get_indexpath
    return "/".join(obj)
TypeError: sequence item 0: expected str instance, bytes found

ProblemType: Bug
DistroRelease: Ubuntu 20.04
Package: rdiff-backup 2.0.0-1
ProcVersionSignature: Ubuntu 5.4.0-26.30-generic 5.4.30
Uname: Linux 5.4.0-26-generic x86_64
NonfreeKernelModules: nvidia_modeset nvidia
ApportVersion: 2.20.11-0ubuntu27
Architecture: amd64
CasperMD5CheckResult: skip
CurrentDesktop: ubuntu:GNOME
Date: Sun Apr 26 06:08:06 2020
InstallationDate: Installed on 2016-12-27 (1215 days ago)
InstallationMedia: Ubuntu-Server 16.10 "Yakkety Yak" - Release amd64 (20161012.1)
SourcePackage: rdiff-backup
UpgradeStatus: Upgraded to focal on 2020-04-25 (0 days ago)

[Otto Kekäläinen (otto)]

Please provide exact steps on how to reproduce this error in a clean Docker image or virtual machine. We cannot debug or fix this if we can't reproduce this.

[Walt Mankowski (waltman)]

I'm afraid I don't know nearly enough Docker to be able to do that. But I do know Python. I just took a look at the code and I think I should be able to trap the TypeError exception pretty easily.

I'm currently running `rdiff-backup --check-destination-dir` to undo the failed backup. Once that finishes I'll rerun the backup in the debugger and report back on what I find. Hopefully that will let me set up a simple test case.

[Walt Mankowski (waltman)]

I modified get_indexpath() in log.py to catch a TypeError exception and return the string "TypeError" instead of aborting. It printed 4 errors:

ListError: 'TypeError' [Errno 13] Permission denied: b'/run/user/1000/doc'
ListError: 'TypeError' [Errno 13] Permission denied: b'/run/user/1000/gvfs'
ListError: 'TypeError' [Errno 13] Permission denied: b'/run/user/1000/keybase/kbfs'
ListError: 'TypeError' [Errno 13] Permission denied: b'/run/user/141/gvfs'

I'm not really sure what's wrong with the first 3. Maybe they're odd because they're in /run? The final file does really look like it might be corrupted.

At any rate it looks like the easy fix on my end is to exclude /run from my backups.

[Eric Hazen (hazen)]

I'm also affected by this bug. It is many months later, but a recent update to some 20.04 package caused this to start happening. Any suggested solutions other than "learn docker, install a new VM etc"?

[Otto Kekäläinen (otto)]

There is nothing actionable in this bug report since there are not steps to reproduce outlined or no test case or anything for developers to use to repeat the bug and test/fix it.

Please contribute to rdiff-backup by debugging the error properly and consider filing a well written bug report at https://github.com/rdiff-backup/rdiff-backup/issues

[Walt Mankowski (waltman)]

My apologies. I resolved this locally back in April but I forgot to come back here and update the ticket when I resolved the problem. This is a known bug that has been fixed in the rdiff-backup repo:

https://github.com/rdiff-backup/rdiff-backup/issues/310

The code was fixed way back in March, but it never made it into 20.04.

Since the files that were causing the errors for me were all in /run, my fix was just to add /run to my list of excluded directories. That was an easy decision for me since I probably should have been excluding them anyway. Good luck!

[Otto Kekäläinen (otto)]

The commit that fixed this was in rdiff-backup version 2.0.5, right?
https://github.com/rdiff-backup/rdiff-backup/commit/1c6b9bcf388bbbef522dd1a752e747a51c6ce004

So a stable release update of rdiff-backup 2.0.5 to Ubuntu 20.04 LTS (Focal) would close this issue?

Could you try using the 2.0.5 version from https://launchpad.net/~rdiff-backup/+archive/ubuntu/rdiff-backup-backports and verify if it fixes the issue?

Landing a stable release update in Ubuntu 20.04 requires very good grounds: https://wiki.ubuntu.com/StableReleaseUpdates

If 2.0.5 is urgently needed in Ubuntu 20.04, please help us document the motivations for it here.

[Walt Mankowski (waltman)]

Hi Otto,

On Fri, Sep 11, 2020 at 06:14:08AM -0000, Otto Kekäläinen wrote:
> The commit that fixed this was in rdiff-backup version 2.0.5, right?
> https://github.com/rdiff-backup/rdiff-backup/commit/1c6b9bcf388bbbef522dd1a752e747a51c6ce004

Hmm, it could be. This is what I based "it was fixed" on:

https://lists.nongnu.org/archive/html/rdiff-backup-users/2020-04/msg00041.html

> So a stable release update of rdiff-backup 2.0.5 to Ubuntu 20.04 LTS
> (Focal) would close this issue?

It seems that way.

> Could you try using the 2.0.5 version from https://launchpad.net/~rdiff-
> backup/+archive/ubuntu/rdiff-backup-backports and verify if it fixes the
> issue?

I'll try, but unfortunately I'm dealing with some serious family
issues right now that are occupying a lot of my time. It might be a
week or two before I can work on it.

>
> Landing a stable release update in Ubuntu 20.04 requires very good
> grounds: https://wiki.ubuntu.com/StableReleaseUpdates
>
> If 2.0.5 is urgently needed in Ubuntu 20.04, please help us document the
> motivations for it here.

Totally understandable.

Walt

[normandrobert (sub1)]

Had same rdiff-backup issue. Got newer rdiff-backup 2.0.5 which handles ¿filesystem problem? gracefully and then "fixed" said problem.

I discovered that my root cron backup script which uses rdiff-backup had been failing for months for the same worrysome reason that rdiff-backup had a problem with a directory it was backing up as root. Confirmed running manually:
.......
File "/usr/lib/python3/dist-packages/rdiff_backup/rpath.py", line 386, in make_file_dict
    statblock = os.lstat(filename)
PermissionError: [Errno 13] Permission denied: b'/home/robert/.cache/doc'
During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/bin/rdiff-backup", line 32, in <module>
    rdiff_backup.Main.error_check_Main(sys.argv[1:])
  File "/usr/lib/python3/dist-packages/rdiff_backup/Main.py", line 390, in error_check_Main
..........

I could not remove the empty directory as the owner or as root. As a workaround, I got a later version of rdiff-backup which continues "gracefully" after encountering the above problem.

sudo apt -y install python3-pip python3-setuptools python3-pylibacl python3-pyxattr
rdiff-backup --version
sudo apt -y remove rdiff-backup
sudo pip3 install rdiff-backup
rdiff-backup --version
# Output: rdiff-backup 2.0.5
rdiff-backup above is in /usr/local/bin

After a few reboots + a manual fsck -V -f on the partition of interest (/dev/sda2 /home) which found nothing, rdiff-backup ran clean and I was finally able to remove the offending directory. I was expecting fsck to have run on the partition of concern at boot and fixed something but there is no evidence it ran on /dev/sda2 /home. Only keeps last boot?
more /run/initramfs/fsck.log
--------------------
Log of fsck -C -a -T -t ext4 /dev/sdd5
Tue Dec 28 15:30:07 2021

/dev/sdd5: clean, 349494/4276224 files, 5482131/17089536 blocks

Tue Dec 28 15:30:07 2021
----------------

GUI Disk utility says disk is ok probably via smartmon. Ran smart short test which is clean:
sudo smartctl -t short /dev/sda
sudo smartctl -l selftest /dev/sda
smartctl 7.1 2019-12-30 r5022 [x86_64-linux-5.11.0-43-generic] (local build)
Copyright (C) 2002-19, Bruce Allen, Christian Franke, www.smartmontools.org

=== START OF READ SMART DATA SECTION ===
SMART Self-test log structure revision number 1
Num Test_Description Status Remaining LifeTime(hours) LBA_of_first_error
# 1 Short offline Completed without error 00% 43344

Running long test now

[Otto Kekäläinen (otto)]

This is not reproducable but based on reports this was indeed fixed in rdiff-backup 2.0.5, so closing bug report now.