Rsync backups don't work after v57 -> v61 upgrade

Help with Setup/Upgrade
1

So I finally did the upgrade, I followed all the steps in the docs, everything seems to work fine as far as I can tell, I can access all my email, send and receive. The one thing that doesn’t seem to work is the rsync backups. When I try to switch to rsync as the backup method as I’ve been using on my box for years, I get this message (instantly, there’s no indication that it’s even trying to connect):

Backup configuration

Connection to rsync host failed: Unknown error.Please check running 'management/backup.py --verify’from mailinabox sources to debug the issue.

When I run the command it tells me to run, this is the output:

~$ sudo mailinabox/management/backup.py --verify

Using archive dir: /home/user-data/backup/cache/77bb3fb2afb5975d26aa819871b4bd44
Using backup name: 77bb3fb2afb5975d26aa819871b4bd44
Import of duplicity.backends.adbackend Succeeded
Import of duplicity.backends.azurebackend Succeeded
Import of duplicity.backends.b2backend Succeeded
Import of duplicity.backends.boxbackend Failed: No module named ‘boxsdk’
Import of duplicity.backends.cfbackend Succeeded
Import of duplicity.backends.dpbxbackend Succeeded
Import of duplicity.backends.gdocsbackend Succeeded
Import of duplicity.backends.gdrivebackend Succeeded
Import of duplicity.backends.giobackend Succeeded
Import of duplicity.backends.hsibackend Succeeded
Import of duplicity.backends.hubicbackend Succeeded
Import of duplicity.backends.idrivedbackend Succeeded
Import of duplicity.backends.imapbackend Succeeded
Import of duplicity.backends.jottacloudbackend Succeeded
Import of duplicity.backends.lftpbackend Succeeded
Import of duplicity.backends.localbackend Succeeded
Import of duplicity.backends.mediafirebackend Succeeded
Import of duplicity.backends.megabackend Succeeded
Import of duplicity.backends.megav2backend Succeeded
Import of duplicity.backends.megav3backend Succeeded
Import of duplicity.backends.multibackend Succeeded
Import of duplicity.backends.ncftpbackend Succeeded
Import of duplicity.backends.onedrivebackend Succeeded
Import of duplicity.backends.par2backend Succeeded
Import of duplicity.backends.pcabackend Succeeded
Import of duplicity.backends.pydrivebackend Succeeded
Import of duplicity.backends.rclonebackend Succeeded
Import of duplicity.backends.rsyncbackend Succeeded
Import of duplicity.backends.s3_boto3_backend Succeeded
Import of duplicity.backends.s3_boto_backend Succeeded
Import of duplicity.backends.slatebackend Succeeded
Import of duplicity.backends.ssh_paramiko_backend Succeeded
Import of duplicity.backends.ssh_pexpect_backend Succeeded
Import of duplicity.backends.swiftbackend Succeeded
Import of duplicity.backends.sxbackend Succeeded
Import of duplicity.backends.tahoebackend Succeeded
Import of duplicity.backends.webdavbackend Succeeded
Main action: verify

================================================================================
duplicity 1.2.1
Args: /usr/bin/duplicity --verbosity info verify --compare-data --archive-dir /home/user-data/backup/cache --exclude /home/user-data/backup file:///home/user-data/backup/encrypted /home/user-data
Linux box.gnite.pl 5.15.0-58-generic #64-Ubuntu SMP Thu Jan 5 11:43:13 UTC 2023 x86_64 x86_64
/usr/bin/python3 3.10.6 (main, Nov 14 2022, 16:10:14) [GCC 11.3.0]

================================================================================
Local and Remote metadata are synchronized, no sync needed.
Last full backup date: none
Using temporary directory /tmp/duplicity-4dm5qj1l-tempdir
Traceback (innermost last):
File “/usr/bin/duplicity”, line 86, in
with_tempdir(main)
File “/usr/bin/duplicity”, line 70, in with_tempdir
fn()
File “/usr/lib/python3/dist-packages/duplicity/dup_main.py”, line 1575, in main
do_backup(action)
File “/usr/lib/python3/dist-packages/duplicity/dup_main.py”, line 1660, in do_backup
verify(col_stats)
File “/usr/lib/python3/dist-packages/duplicity/dup_main.py”, line 910, in verify
collated = diffdir.collate2iters(restore_get_patched_rop_iter(col_stats),
File “/usr/lib/python3/dist-packages/duplicity/dup_main.py”, line 771, in restore_get_patched_rop_iter
backup_chain = col_stats.get_backup_chain_at_time(time)
File “/usr/lib/python3/dist-packages/duplicity/dup_collections.py”, line 988, in get_backup_chain_at_time
raise CollectionsError(u"No backup chains found")
duplicity.dup_collections.CollectionsError: No backup chains found

Traceback (most recent call last):
File “/home/gnite/mailinabox/management/utils.py”, line 126, in shell
ret = getattr(subprocess, method)(cmd_args, **kwargs)
File “/usr/lib/python3.10/subprocess.py”, line 369, in check_call
raise CalledProcessError(retcode, cmd)
subprocess.CalledProcessError: Command ‘[’/usr/bin/duplicity’, ‘–verbosity’, ‘info’, ‘verify’, ‘–compare-data’, ‘–archive-dir’, ‘/home/user-data/backup/cache’, ‘–exclude’, ‘/home/user-data/backup’, ‘file:///home/user-data/backup/encrypted’, ‘/home/user-data’]’ returned non-zero exit status 30.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File “/home/gnite/mailinabox/management/backup.py”, line 592, in
run_duplicity_verification()
File “/home/gnite/mailinabox/management/backup.py”, line 383, in run_duplicity_verification
shell(‘check_call’, [
File “/home/gnite/mailinabox/management/utils.py”, line 133, in shell
raise Exception(msg)
Exception: Command failed with exit code 30: /usr/bin/duplicity --verbosity info verify --compare-data --archive-dir /home/user-data/backup/cache --exclude /home/user-data/backup file:///home/user-data/backup/encrypted /home/user-data

Oh and to state the obvious, I did add the new public key to the target server.

2

The real error is a bit hidden in the error message:

duplicity.dup_collections.CollectionsError: No backup chains found

Reasons for this could be:

  • (For me most likely): Your encryption key changed by upgrading to a new box. You can just set /home/user-data/backup/secret_key.txt to your old secret_key.txt. Maybe this fixes the error.

  • I read somewhere that sometimes a “/” at the end of the path is missing.

  • Maybe some more googling required

3

Thank you for replying. The target directory at the backup server is empty. Correct me if I’m wrong, but the secret key shouldn’t matter in such case, no? Anyway, I did try it with the old one and the same thing happens. I’m unable to set it to rsync backups in the administration panel in the first place. It defaults to local backups and these seem to work, even though there’s still the

returned non-zero exit status 1

error at the end. When I try to switch to rsync (with or without the trailing “/” at the end of the path, makes no difference), the moment I hit save I get the error message from my original post, like I said, it looks like it’s not even trying to connect to the remote server. The error you quoted looks like was due to the fact that I ran it on a fresh install when no backups have been performed yet, it no longer shows up. This is the current output:

Using archive dir: /home/user-data/backup/cache/77bb3fb2afb5975d26aa819871b4bd44
Using backup name: 77bb3fb2afb5975d26aa819871b4bd44
Import of duplicity.backends.adbackend Succeeded
Import of duplicity.backends.azurebackend Succeeded
Import of duplicity.backends.b2backend Succeeded
Import of duplicity.backends.boxbackend Failed: No module named ‘boxsdk’
Import of duplicity.backends.cfbackend Succeeded
Import of duplicity.backends.dpbxbackend Succeeded
Import of duplicity.backends.gdocsbackend Succeeded
Import of duplicity.backends.gdrivebackend Succeeded
Import of duplicity.backends.giobackend Succeeded
Import of duplicity.backends.hsibackend Succeeded
Import of duplicity.backends.hubicbackend Succeeded
Import of duplicity.backends.idrivedbackend Succeeded
Import of duplicity.backends.imapbackend Succeeded
Import of duplicity.backends.jottacloudbackend Succeeded
Import of duplicity.backends.lftpbackend Succeeded
Import of duplicity.backends.localbackend Succeeded
Import of duplicity.backends.mediafirebackend Succeeded
Import of duplicity.backends.megabackend Succeeded
Import of duplicity.backends.megav2backend Succeeded
Import of duplicity.backends.megav3backend Succeeded
Import of duplicity.backends.multibackend Succeeded
Import of duplicity.backends.ncftpbackend Succeeded
Import of duplicity.backends.onedrivebackend Succeeded
Import of duplicity.backends.par2backend Succeeded
Import of duplicity.backends.pcabackend Succeeded
Import of duplicity.backends.pydrivebackend Succeeded
Import of duplicity.backends.rclonebackend Succeeded
Import of duplicity.backends.rsyncbackend Succeeded
Import of duplicity.backends.s3_boto3_backend Succeeded
Import of duplicity.backends.s3_boto_backend Succeeded
Import of duplicity.backends.slatebackend Succeeded
Import of duplicity.backends.ssh_paramiko_backend Succeeded
Import of duplicity.backends.ssh_pexpect_backend Succeeded
Import of duplicity.backends.swiftbackend Succeeded
Import of duplicity.backends.sxbackend Succeeded
Import of duplicity.backends.tahoebackend Succeeded
Import of duplicity.backends.webdavbackend Succeeded
Main action: verify

================================================================================
duplicity 1.2.1
Args: /usr/bin/duplicity --verbosity info verify --compare-data --archive-dir /home/user-data/backup/cache --exclude /home/user-data/backup file:///home/user-data/backup/encrypted /home/user-data
Linux box.gnite.pl 5.15.0-58-generic #64-Ubuntu SMP Thu Jan 5 11:43:13 UTC 2023 x86_64 x86_64
/usr/bin/python3 3.10.6 (main, Nov 14 2022, 16:10:14) [GCC 11.3.0]

================================================================================
Processing local manifest b’/home/user-data/backup/cache/77bb3fb2afb5975d26aa819871b4bd44/duplicity-inc.20230124T022708Z.to.20230125T020808Z.manifest’ (4324)
Found 1 volumes in manifest
Processing local manifest b’/home/user-data/backup/cache/77bb3fb2afb5975d26aa819871b4bd44/duplicity-full.20230124T022708Z.manifest’ (29113945)
Found 14 volumes in manifest
Added incremental Backupset (start_time: Tue Jan 24 03:27:08 2023 / end_time: Wed Jan 25 03:08:08 2023)
Local and Remote metadata are synchronized, no sync needed.
Last full backup date: Tue Jan 24 03:27:08 2023
Processing local manifest b’/home/user-data/backup/cache/77bb3fb2afb5975d26aa819871b4bd44/duplicity-full.20230124T022708Z.manifest’ (29113945)
Found 14 volumes in manifest
Processing local manifest b’/home/user-data/backup/cache/77bb3fb2afb5975d26aa819871b4bd44/duplicity-inc.20230124T022708Z.to.20230125T020808Z.manifest’ (4324)
Found 1 volumes in manifest
Processing local manifest b’/home/user-data/backup/cache/77bb3fb2afb5975d26aa819871b4bd44/duplicity-full.20230124T022708Z.manifest’ (29113945)
Found 14 volumes in manifest
Using temporary directory /tmp/duplicity-50iphst2-tempdir
Processing local manifest b’/home/user-data/backup/cache/77bb3fb2afb5975d26aa819871b4bd44/duplicity-inc.20230124T022708Z.to.20230125T020808Z.manifest’ (4324)
Found 1 volumes in manifest
Difference found: File mail/mailboxes/gnite.pl/gnite has mtime Wed Jan 25 21:49:48 2023, expected Tue Jan 24 22:13:30 2023
Deleting /tmp/duplicity-50iphst2-tempdir/mktemp-ymrnu40x-1
Processed volume 1 of 15
Difference found: File mail/mailboxes/gnite.pl/gnite/.Sent has mtime Thu Jan 26 00:07:34 2023, expected Wed Jan 25 02:53:41 2023
Deleting /tmp/duplicity-50iphst2-tempdir/mktemp-s66mhs4k-3
Processed volume 2 of 15
Deleting /tmp/duplicity-50iphst2-tempdir/mktemp-6lb7r6oz-4
Processed volume 3 of 15
Difference found: File mail/mailboxes/gnite.pl/gnite/.Sent/dovecot.index.cache has mtime Wed Jan 25 17:27:25 2023, expected Tue Jan 24 17:08:48 2023
Difference found: File mail/mailboxes/gnite.pl/gnite/.Trash has mtime Wed Jan 25 15:21:49 2023, expected Tue Jan 24 19:00:00 2023
Difference found: File mail/mailboxes/gnite.pl/gnite/.Trash/cur has mtime Wed Jan 25 13:17:59 2023, expected Tue Jan 24 18:51:22 2023>
Difference found: New file mail/mailboxes/gnite.pl/gnite/.Trash/cur/1674624518.M268597P382296.box.gnite.pl,S=36957,W=37743:2,S
Difference found: New file mail/mailboxes/gnite.pl/gnite/.Trash/cur/1674628334.M12330P393505.box.gnite.pl,S=54601,W=55845:2,
Difference found: New file mail/mailboxes/gnite.pl/gnite/.Trash/cur/1674647577.M392500P442390.box.gnite.pl,S=74656,W=76345:2,S
Difference found: File mail/mailboxes/gnite.pl/gnite/.Trash/dovecot-uidlist has mtime Wed Jan 25 13:17:59 2023, expected Tue Jan 24 18:51:22 2023
Difference found: File mail/mailboxes/gnite.pl/gnite/.Trash/dovecot.index.cache has mtime Wed Jan 25 13:17:59 2023, expected Tue Jan 24 18:51:22 2023
Difference found: File mail/mailboxes/gnite.pl/gnite/.Trash/dovecot.index.log has mtime Wed Jan 25 15:21:49 2023, expected Tue Jan 24 19:00:00 2023
Difference found: File mail/mailboxes/gnite.pl/gnite/.Trash/new has mtime Wed Jan 25 07:44:02 2023, expected Sat Jan 21 17:21:56 2023
Difference found: File mail/mailboxes/gnite.pl/gnite/.Trash/tmp has mtime Wed Jan 25 13:17:59 2023, expected Tue Jan 24 18:51:22 2023
Difference found: File mail/mailboxes/gnite.pl/gnite/cur has mtime Wed Jan 25 20:33:48 2023, expected Tue Jan 24 22:01:39 2023
Deleting /tmp/duplicity-50iphst2-tempdir/mktemp-2wxkdo4s-5
Processed volume 4 of 15
Deleting /tmp/duplicity-50iphst2-tempdir/mktemp-se1lyp6_-6
Processed volume 5 of 15
Deleting /tmp/duplicity-50iphst2-tempdir/mktemp-3k_wao73-7
Processed volume 6 of 15
Deleting /tmp/duplicity-50iphst2-tempdir/mktemp-cy9sluu5-8
Processed volume 7 of 15
Deleting /tmp/duplicity-50iphst2-tempdir/mktemp-4d4wjjvz-9
Processed volume 8 of 15
Difference found: New file mail/mailboxes/gnite.pl/gnite/cur/1674612582.M928218P353854.box.gnite.pl,S=13841,W=14047:2,S
Difference found: New file mail/mailboxes/gnite.pl/gnite/cur/1674673383.M160062P517040.box.gnite.pl,S=9978,W=10222:2,S
Difference found: File mail/mailboxes/gnite.pl/gnite/dovecot-uidlist has mtime Wed Jan 25 20:03:03 2023, expected Tue Jan 24 21:49:31 2023
Difference found: File mail/mailboxes/gnite.pl/gnite/dovecot.index has mtime Wed Jan 25 20:03:03 2023, expected Tue Jan 24 09:33:44 2023
Difference found: File mail/mailboxes/gnite.pl/gnite/dovecot.index.cache has mtime Wed Jan 25 20:03:03 2023, expected Tue Jan 24 21:49:31 2023
Difference found: File mail/mailboxes/gnite.pl/gnite/dovecot.index.log has mtime Wed Jan 25 20:33:51 2023, expected Tue Jan 24 22:01:42 2023
Difference found: File mail/mailboxes/gnite.pl/gnite/dovecot.list.index.log has mtime Wed Jan 25 15:21:49 2023, expected Tue Jan 24 19:05:02 2023
Difference found: File mail/mailboxes/gnite.pl/gnite/new has mtime Wed Jan 25 20:03:03 2023, expected Tue Jan 24 21:49:31 2023
Difference found: File mail/mailboxes/gnite.pl/gnite/tmp has mtime Wed Jan 25 20:03:03 2023, expected Tue Jan 24 21:49:31 2023
Difference found: File mail/postgrey/db has mtime Wed Jan 25 03:09:25 2023, expected Tue Jan 24 18:57:34 2023
Difference found: File mail/postgrey/db/__db.001 has mtime Wed Jan 25 20:09:15 2023, expected Wed Jan 25 03:08:08 2023
Difference found: File mail/postgrey/db/__db.002 has mtime Wed Jan 25 20:09:15 2023, expected Wed Jan 25 03:08:08 2023
Difference found: File mail/postgrey/db/__db.003 has mtime Wed Jan 25 20:09:15 2023, expected Wed Jan 25 03:08:08 2023
Difference found: File mail/postgrey/db/log.0000000001 has mtime Wed Jan 25 20:09:15 2023, expected Tue Jan 24 21:49:26 2023
Difference found: File mail/postgrey/db/postgrey.db has mtime Wed Jan 25 20:09:15 2023, expected Tue Jan 24 21:49:26 2023
Difference found: File mail/postgrey/db/postgrey_clients.db has mtime Wed Jan 25 20:09:15 2023, expected Tue Jan 24 21:49:26 2023
Difference found: File mail/sieve/gnite.pl has mtime Wed Jan 25 20:09:20 2023, expected Fri Mar 11 11:47:49 2022
Difference found: File mail/sieve/gnite.pl/junk.svbin has mtime Wed Jan 25 20:09:20 2023, expected Tue Oct 19 14:07:42 2021
Difference found: File mail/spamassassin has mtime Wed Jan 25 20:03:03 2023, expected Tue Jan 24 21:49:31 2023
Difference found: File mail/spamassassin/bayes_journal has mtime Wed Jan 25 20:09:16 2023, expected Tue Jan 24 21:49:27 2023
Difference found: File mail/spamassassin/bayes_seen has mtime Wed Jan 25 20:03:03 2023, expected Tue Jan 24 21:49:31 2023
Difference found: File mail/spamassassin/bayes_toks has mtime Wed Jan 25 20:03:03 2023, expected Tue Jan 24 21:49:31 2023
Difference found: File owncloud has mtime Thu Jan 26 00:21:01 2023, expected Wed Jan 25 03:08:00 2023
Difference found: File owncloud/appdata_ocxxxxxxxxx/appstore/apps.json has mtime Wed Jan 25 17:05:58 2023, expected Tue Jan 24 17:01:18 2023
Difference found: File owncloud/owncloud.db has mtime Thu Jan 26 00:21:01 2023, expected Wed Jan 25 03:08:00 2023
Deleting /tmp/duplicity-50iphst2-tempdir/mktemp-gjmswgwg-2
Processed volume 9 of 15
Deleting /tmp/duplicity-50iphst2-tempdir/mktemp-o_v74hpm-10
Processed volume 10 of 15
Deleting /tmp/duplicity-50iphst2-tempdir/mktemp-clu08qny-11
Processed volume 11 of 15
Deleting /tmp/duplicity-50iphst2-tempdir/mktemp-7mr89c59-12
Processed volume 12 of 15
Deleting /tmp/duplicity-50iphst2-tempdir/mktemp-jlipy3si-13
Processed volume 13 of 15
Deleting /tmp/duplicity-50iphst2-tempdir/mktemp-b6sc1gte-14
Processed volume 14 of 15
Deleting /tmp/duplicity-50iphst2-tempdir/mktemp-kp867dso-15
Processed volume 15 of 15
Verify complete: 292575 file(s) compared, 39 difference(s) found.
Traceback (most recent call last):
File “/home/gnite/mailinabox/management/utils.py”, line 126, in shell
ret = getattr(subprocess, method)(cmd_args, **kwargs)
File “/usr/lib/python3.10/subprocess.py”, line 369, in check_call
raise CalledProcessError(retcode, cmd)
subprocess.CalledProcessError: Command ‘[’/usr/bin/duplicity’, ‘–verbosity’, ‘info’, ‘verify’, ‘–compare-data’, ‘–archive-dir’, ‘/home/user-data/backup/cache’, ‘–exclude’, ‘/home/user-data/backup’, ‘file:///home/user-data/backup/encrypted’, ‘/home/user-data’]’ returned non-zero exit status 1.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File “/home/gnite/mailinabox/management/backup.py”, line 592, in
run_duplicity_verification()
File “/home/gnite/mailinabox/management/backup.py”, line 383, in run_duplicity_verification
shell(‘check_call’, [
File “/home/gnite/mailinabox/management/utils.py”, line 133, in shell
raise Exception(msg)
Exception: Command failed with exit code 1: /usr/bin/duplicity --verbosity info verify --compare-data --archive-dir /home/user-data/backup/cache --exclude /home/user-data/backup file:///home/user-data/backup/encrypted /home/user-data

4

I see. Currently there is a bug in which rsync does not work when no port is set. Please set the port manually to 22 (Add :22 after the IP). This is likely to be fixed in the next release, however this hotfix should work as well.

(see fix(rsync-backup): Provide default port 22 for rsync usage in backup.py by hughsw · Pull Request #2226 · mail-in-a-box/mailinabox · GitHub for reference)

1 Like
5

This fixed the problem, thank you!

6

This topic was automatically closed 7 days after the last reply. New replies are no longer allowed.