Package: rsync
Version: 3.2.3-2
Severity: important
Dear Maintainer,
* What led up to the situation?
I believe the problem started with the latest update of the rsync package end
of 08/2020. A previously working setup of backuppc reproducibly fails for a
specific host and specific directory tree since then.
* What exactly did you do (or not do) that was effective (or
ineffective)?
I repeatedly restarted the backup from BackupPC, all failing.
I conducted a test rsynch over ssh directly without BackupPC, all failing.
I checked dmesg for indications of lower level problems, there are none.
* What was the outcome of this action?
1) With BackupPC
-- Output of
/usr/share/backuppc/bin/BackupPC_zcat
/var/lib/backuppc/pc/localhost/XferLOG.z|grep -v -a '^ '
full backup started for directory /var/lib/lxc (baseline backup #131)
Running: /usr/bin/ssh -q -x -l root localhost /usr/bin/rsync --server --sender
--numeric-ids \
--perms --owner --group -D --links --hard-links --times --block-size=2048
--recursive \
--one-file-system --ignore-times . /var/lib/lxc/
Xfer PIDs are now 77976
Got remote protocol 31
Negotiated protocol version 28
Sent exclude: tmp
Sent exclude: temp
Sent exclude: *Trash*
Sent exclude: trash*
Sent exclude: backup*
Sent exclude: *.bak
Sent exclude: *.tmp
Xfer PIDs are now 77976,78855
Remote[-7]:
Remote[98]: <<here starts binary content, obviously file content meant to be
transmitted, pushing the log file to several GiB>>
-- end of filtered log
-- Another run, the output looks like:
incr backup started back to 2020-08-19 22:00:03 (backup #127) for directory
/var/lib/lxc
Running: /usr/bin/ssh -q -x -l root localhost /usr/bin/rsync --server --sender
--numeric-ids --perms --owner --group -D --links --hard-links --times
--block-size=2048 --recursive --one-file-system . /var/lib/lxc/
Xfer PIDs are now 23770
Got remote protocol 31
Negotiated protocol version 28
Sent exclude: tmp
Sent exclude: temp
Sent exclude: *Trash*
Sent exclude: trash*
Sent exclude: backup*
Sent exclude: *.bak
Sent exclude: *.tmp
Xfer PIDs are now 23770,24835
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[41]:
<C0>^@^G^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
Remote[-7]:
<<.... thousands of identical lines>>
<<...binary garbage>>
--
Finally, rsync (and BackupPC_dump) just hang around each waiting for something
to happen:
-- Output of strace on rsync's PID:
strace: Process 23781 attached
select(2, [], [1], [], {tv_sec=35, tv_usec=526085}) = 0 (Timeout)
select(2, [], [1], [], {tv_sec=60, tv_usec=0}) = 0 (Timeout)
select(2, [], [1], [], {tv_sec=60, tv_usec=0}) = 0 (Timeout)
select(2, [], [1], [], {tv_sec=60, tv_usec=0}^Cstrace: Process 23781 detached
<detached ...>
--
It is required to stop the BackupPC service, or to manually kill BackupPC_dump
and/or rsync.
2) rsync test run
-- rsync stdout
opening connection using: ssh -l root localhost rsync --server --sender
-vvvlHogDtprxe.iLsfxCIvu -B2048 --numeric-ids . /var/lib/lxc (12 args)
receiving incremental file list
server_sender starting pid=144226
[sender] make_file(lxc,*,0)
send_file_list done
[sender] pushing local filters for /var/lib/lxc/
<<very much diagnostics of transferring thousands of files without problems>>
got file_sum
set modtime, atime of lxc/nextcloud/rootfs/var/backups/.gshadow.bak.vcUsMX to
(1596971541) 2020/08/09 13:12:21, (1599125234) 2020/09/03 11:27:14
renaming lxc/nextcloud/rootfs/var/backups/.gshadow.bak.vcUsMX to
lxc/nextcloud/rootfs/var/backups/gshadow.bak
recv_files(lxc/nextcloud/rootfs/var/backups/nextcloud-dir_20200119.tar)
lxc/nextcloud/rootfs/var/backups/nextcloud-dir_20200119.tar
[receiver] _exit_cleanup(code=13, file=log.c, line=245): about to call exit(13)
[generator] _exit_cleanup(code=13, file=io.c, line=1644): about to call exit(13)
-- end of stdout
-- rsync stderr
rsync error: errors with program diagnostics (code 13) at log.c(245)
[receiver=3.2.3]
rsync: [generator] write error: Broken pipe (32)
-- end of stderr
3) tar file generation
...just worked
* What outcome did you expect instead?
A copy of the source directory tree at the destination ;-)
-- System Information:
Debian Release: bullseye/sid
APT prefers testing
APT policy: (990, 'testing'), (500, 'stable')
Architecture: amd64 (x86_64)
Foreign Architectures: i386
Kernel: Linux 5.7.0-3-amd64 (SMP w/4 CPU threads)
Kernel taint flags: TAINT_FIRMWARE_WORKAROUND
Locale: LANG=de_DE.UTF-8, LC_CTYPE=de_DE.UTF-8 (charmap=UTF-8), LANGUAGE not set
Shell: /bin/sh linked to /bin/bash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled
Versions of packages rsync depends on:
ii init-system-helpers 1.58
ii libacl1 2.2.53-8
ii libc6 2.31-3
ii liblz4-1 1.9.2-2
ii libpopt0 1.18-1
ii libssl1.1 1.1.1g-1
ii libxxhash0 0.8.0-1
ii libzstd1 1.4.5+dfsg-4
ii lsb-base 11.1.0
ii zlib1g 1:1.2.11.dfsg-2
rsync recommends no packages.
Versions of packages rsync suggests:
ii openssh-client 1:8.3p1-1
ii openssh-server 1:8.3p1-1
ii python3 3.8.2-3
-- no debconf information
