LXC Suspend-mode backup rsync error 23

theokonos

Member
Aug 18, 2021
1
0
6
32
Good evening,

One of my CTs suddenly started failing its nightly backups:

Code:
INFO: starting new backup job: vzdump 105 --remove 0 --compress zstd --mode snapshot --node p-body --storage local
INFO: Starting Backup of VM 105 (lxc)
INFO: Backup started at 2021-08-17 17:52:07
INFO: status = running
INFO: CT Name: postgres
INFO: including mount point rootfs ('/') in backup
INFO: mode failure - some volumes do not support snapshots
INFO: trying 'suspend' mode instead
INFO: backup mode: suspend
INFO: ionice priority: 7
INFO: CT Name: postgres
INFO: including mount point rootfs ('/') in backup
INFO: starting first sync /proc/3079981/root/ to /var/lib/vz/dump/vzdump-lxc-105-2021_08_17-17_52_07.tmp
INFO: first sync finished - transferred 9.62G bytes in 276s
INFO: suspending guest
INFO: starting final sync /proc/3079981/root/ to /var/lib/vz/dump/vzdump-lxc-105-2021_08_17-17_52_07.tmp
INFO: resume vm
INFO: guest is online again after 8 seconds
ERROR: Backup of VM 105 failed - command 'rsync --stats -h -X -A --numeric-ids -aH --delete --no-whole-file --inplace --one-file-system --relative '--exclude=/tmp/?*' '--exclude=/var/tmp/?*' '--exclude=/var/run/?*.pid' /proc/3079981/root//./ /var/lib/vz/dump/vzdump-lxc-105-2021_08_17-17_52_07.tmp' failed: exit code 23
INFO: Failed at 2021-08-17 17:56:57
INFO: Backup job finished with errors
TASK ERROR: job errors

In my testing, a Stop-mode backup works fine but Suspend does not. It also makes no difference if I back up to my NFS storage (PBS) or to local storage.

When I run the rsync manually, it completes without issue. For some reason the error seems to appear after the rsync actually finishes.

Here's my pveversion -v

Code:
proxmox-ve: 7.0-2 (running kernel: 5.11.22-3-pve)
pve-manager: 7.0-10 (running version: 7.0-10/d2f465d3)
pve-kernel-5.11: 7.0-6
pve-kernel-helper: 7.0-6
pve-kernel-5.4: 6.4-5
pve-kernel-5.11.22-3-pve: 5.11.22-6
pve-kernel-5.4.128-1-pve: 5.4.128-1
pve-kernel-5.4.124-1-pve: 5.4.124-2
pve-kernel-5.4.78-2-pve: 5.4.78-2
pve-kernel-5.4.73-1-pve: 5.4.73-1
ceph-fuse: 14.2.21-1
corosync: 3.1.2-pve2
criu: 3.15-1+pve-1
glusterfs-client: 9.2-1
ifupdown: residual config
ifupdown2: 3.1.0-1+pmx3
ksm-control-daemon: 1.4-1
libjs-extjs: 7.0.0-1
libknet1: 1.21-pve1
libproxmox-acme-perl: 1.2.0
libproxmox-backup-qemu0: 1.2.0-1
libpve-access-control: 7.0-4
libpve-apiclient-perl: 3.2-1
libpve-common-perl: 7.0-5
libpve-guest-common-perl: 4.0-2
libpve-http-server-perl: 4.0-2
libpve-storage-perl: 7.0-9
libqb0: 1.0.5-1
libspice-server1: 0.14.3-2.1
lvm2: 2.03.11-2.1
lxc-pve: 4.0.9-4
lxcfs: 4.0.8-pve2
novnc-pve: 1.2.0-3
proxmox-backup-client: 2.0.7-1
proxmox-backup-file-restore: 2.0.7-1
proxmox-mini-journalreader: 1.2-1
proxmox-widget-toolkit: 3.3-6
pve-cluster: 7.0-3
pve-container: 4.0-8
pve-docs: 7.0-5
pve-edk2-firmware: 3.20200531-1
pve-firewall: 4.2-2
pve-firmware: 3.2-4
pve-ha-manager: 3.3-1
pve-i18n: 2.4-1
pve-qemu-kvm: 6.0.0-2
pve-xtermjs: 4.12.0-1
qemu-server: 7.0-13
smartmontools: 7.2-pve2
spiceterm: 3.2-2
vncterm: 1.7-1
zfsutils-linux: 2.0.5-pve1

Any help would be appreciated!

Thanks,
Theo
 
Could you manually run the command with additional -v --progress arguments?
 
I think you mean we should run rsync manual? vzdump does not support the Aruments -v --progress

Edit: I get the right log while the backup job was running, I passed a bash file with the arguments and a log output to the original rsync location:

Code:
2021/08/31 09:00:54 [3886663] Number of files: 66,603 (reg: 51,291, dir: 7,814, link: 7,466, dev: 2, special: 30)
2021/08/31 09:00:54 [3886663] Number of created files: 66,602 (reg: 51,291, dir: 7,813, link: 7,466, dev: 2, special: 30)
2021/08/31 09:00:54 [3886663] Number of deleted files: 0
2021/08/31 09:00:54 [3886663] Number of regular files transferred: 51,065
2021/08/31 09:00:54 [3886663] Total file size: 41.12G bytes
2021/08/31 09:00:54 [3886663] Total transferred file size: 40.89G bytes
2021/08/31 09:00:54 [3886663] Literal data: 40.90G bytes
2021/08/31 09:00:54 [3886663] Matched data: 0 bytes
2021/08/31 09:00:54 [3886663] File list size: 2.29M
2021/08/31 09:00:54 [3886663] File list generation time: 0.001 seconds
2021/08/31 09:00:54 [3886663] File list transfer time: 0.000 seconds
2021/08/31 09:00:54 [3886663] Total bytes sent: 40.91G
2021/08/31 09:00:54 [3886663] Total bytes received: 1.05M
2021/08/31 09:00:54 [3886663] sent 40.91G bytes  received 1.05M bytes  183.87M bytes/sec
2021/08/31 09:00:54 [3886663] total size is 41.12G  speedup is 1.01
2021/08/31 09:00:54 [3890590] building file list
2021/08/31 09:01:00 [3890590] .d..t...... var/lib/icinga2/
2021/08/31 09:01:00 [3890590] >f.st...... var/lib/icinga2/icinga2.state
2021/08/31 09:01:00 [3890590] >f..t...... var/lib/icinga2/modified-attributes.conf
2021/08/31 09:01:00 [3890590] >f.st...... var/lib/influxdb/wal/_internal/monitor/384/_00056.wal
2021/08/31 09:01:00 [3890590] >f.st...... var/lib/influxdb/wal/icinga2/autogen/382/_00002.wal
2021/08/31 09:01:00 [3890590] .d..t...... var/lib/influxdb/wal/proxmox/autogen/381/
2021/08/31 09:01:00 [3890590] >f..t...... var/lib/influxdb/wal/proxmox/autogen/381/_00090.wal
2021/08/31 09:01:00 [3890590] >f+++++++++ var/lib/influxdb/wal/proxmox/autogen/381/_00091.wal
2021/08/31 09:01:00 [3890590] .d..t...... var/lib/influxdb/wal/proxmox2/autogen/383/
2021/08/31 09:01:00 [3890590] >f..t...... var/lib/influxdb/wal/proxmox2/autogen/383/_00145.wal
2021/08/31 09:01:00 [3890590] >f+++++++++ var/lib/influxdb/wal/proxmox2/autogen/383/_00146.wal
2021/08/31 09:01:00 [3890590] >f..t...... var/lib/mysql/ib_logfile0
2021/08/31 09:01:00 [3890590] >f..t...... var/lib/mysql/ibdata1
2021/08/31 09:01:00 [3890590] >f..t...... var/lib/mysql/ibtmp1
2021/08/31 09:01:01 [3890590] >f..t...... var/lib/mysql/icinga2/icinga_hoststatus.ibd
2021/08/31 09:01:01 [3890590] >f..t...... var/lib/mysql/icinga2/icinga_programstatus.ibd
2021/08/31 09:01:01 [3890590] >f..t...... var/lib/mysql/icinga2/icinga_runtimevariables.ibd
2021/08/31 09:01:01 [3890590] >f..t...... var/lib/mysql/icinga2/icinga_servicestatus.ibd
2021/08/31 09:01:01 [3890590] >f..t...... var/lib/mysql/icinga2/icinga_statehistory.ibd
2021/08/31 09:01:01 [3890590] >f..t...... var/lib/mysql/mysql/innodb_index_stats.ibd
2021/08/31 09:01:01 [3890590] >f..t...... var/lib/mysql/mysql/innodb_table_stats.ibd
2021/08/31 09:01:01 [3890590] >f..t...... var/lib/php/sessions/sess_upp9omc1i4c3qoep26kko4gjb4
2021/08/31 09:01:01 [3890590] >f.st...... var/log/syslog
2021/08/31 09:01:01 [3890590] >f.st...... var/log/apache2/access.log
2021/08/31 09:01:01 [3890590] >f.st...... var/log/icinga2/icinga2.log
2021/08/31 09:01:01 [3890590] >f..t...... var/log/journal/5311003402dc4478b04f0b6410e0ab23/system.journal
2021/08/31 09:01:01 [3890590] Number of files: 66,605 (reg: 51,293, dir: 7,814, link: 7,466, dev: 2, special: 30)
2021/08/31 09:01:01 [3890590] Number of created files: 2 (reg: 2)
2021/08/31 09:01:01 [3890590] Number of deleted files: 0
2021/08/31 09:01:01 [3890590] Number of regular files transferred: 23
2021/08/31 09:01:01 [3890590] Total file size: 41.13G bytes
2021/08/31 09:01:01 [3890590] Total transferred file size: 462.28M bytes
2021/08/31 09:01:01 [3890590] Literal data: 8.78M bytes
2021/08/31 09:01:01 [3890590] Matched data: 453.50M bytes
2021/08/31 09:01:01 [3890590] File list size: 262.11K
2021/08/31 09:01:01 [3890590] File list generation time: 0.001 seconds
2021/08/31 09:01:01 [3890590] File list transfer time: 0.000 seconds
2021/08/31 09:01:01 [3890590] Total bytes sent: 11.00M
2021/08/31 09:01:01 [3890590] Total bytes received: 404.83K
2021/08/31 09:01:01 [3890590] sent 11.00M bytes  received 404.83K bytes  1.52M bytes/sec
2021/08/31 09:01:01 [3890590] total size is 41.13G  speedup is 3,606.38
2021/08/31 09:01:01 [3890590] sent 10998957 bytes  received 404839 bytes  total size 41126391210
2021/08/31 09:01:01 [3890590] rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1330) [sender=3.2.3]

Edit2:
Code:
2021/08/31 09:09:45 [3898573] Number of files: 60,417 (reg: 46,724, dir: 7,575, link: 6,087, special: 31)
2021/08/31 09:09:45 [3898573] Number of created files: 60,416 (reg: 46,724, dir: 7,574, link: 6,087, special: 31)
2021/08/31 09:09:45 [3898573] Number of deleted files: 0
2021/08/31 09:09:45 [3898573] Number of regular files transferred: 46,705
2021/08/31 09:09:45 [3898573] Total file size: 1.66G bytes
2021/08/31 09:09:45 [3898573] Total transferred file size: 1.53G bytes
2021/08/31 09:09:45 [3898573] Literal data: 1.53G bytes
2021/08/31 09:09:45 [3898573] Matched data: 0 bytes
2021/08/31 09:09:45 [3898573] File list size: 1.83M
2021/08/31 09:09:45 [3898573] File list generation time: 0.001 seconds
2021/08/31 09:09:45 [3898573] File list transfer time: 0.000 seconds
2021/08/31 09:09:45 [3898573] Total bytes sent: 1.53G
2021/08/31 09:09:45 [3898573] Total bytes received: 950.27K
2021/08/31 09:09:45 [3898573] sent 1.53G bytes  received 950.27K bytes  50.27M bytes/sec
2021/08/31 09:09:45 [3898573] total size is 1.66G  speedup is 1.09
2021/08/31 09:09:45 [3899319] building file list
2021/08/31 09:09:48 [3899319] Number of files: 60,417 (reg: 46,724, dir: 7,575, link: 6,087, special: 31)
2021/08/31 09:09:48 [3899319] Number of created files: 0
2021/08/31 09:09:48 [3899319] Number of deleted files: 0
2021/08/31 09:09:48 [3899319] Number of regular files transferred: 0
2021/08/31 09:09:48 [3899319] Total file size: 1.66G bytes
2021/08/31 09:09:48 [3899319] Total transferred file size: 0 bytes
2021/08/31 09:09:48 [3899319] Literal data: 0 bytes
2021/08/31 09:09:48 [3899319] Matched data: 0 bytes
2021/08/31 09:09:48 [3899319] File list size: 131.07K
2021/08/31 09:09:48 [3899319] File list generation time: 0.001 seconds
2021/08/31 09:09:48 [3899319] File list transfer time: 0.000 seconds
2021/08/31 09:09:48 [3899319] Total bytes sent: 1.69M
2021/08/31 09:09:48 [3899319] Total bytes received: 8.00K
2021/08/31 09:09:48 [3899319] sent 1.69M bytes  received 8.00K bytes  484.56K bytes/sec
2021/08/31 09:09:48 [3899319] total size is 1.66G  speedup is 980.86

Edit3:
With some more debugging (-vv --progress) I found the following Lines:

First Sync:
total: matches=0 hash_hits=0 false_alarms=0 data=40935316292

Second Sync:
total: matches=58378 hash_hits=242944 false_alarms=7 data=5894890

I think it's related to the false_alarms.
Code:
2021/08/31 10:20:38 [3993559] [sender] hiding directory tmp/.font-unix because of pattern /tmp/?*
2021/08/31 10:20:38 [3993559] [sender] hiding directory tmp/.ICE-unix because of pattern /tmp/?*
2021/08/31 10:20:38 [3993559] [sender] hiding directory tmp/.XIM-unix because of pattern /tmp/?*
2021/08/31 10:20:38 [3993559] [sender] hiding directory tmp/.Test-unix because of pattern /tmp/?*
2021/08/31 10:20:38 [3993559] [sender] hiding directory tmp/.X11-unix because of pattern /tmp/?*
2021/08/31 10:20:38 [3993559] [sender] hiding directory tmp/systemd-private-f715f1c95d39480aa210ced54c3381ea-apache2.service-s4v9n4 because of pattern /tmp/?*
2021/08/31 10:20:38 [3993559] [sender] hiding directory tmp/systemd-private-f715f1c95d39480aa210ced54c3381ea-systemd-resolved.service-UPwgrm because of pattern /tmp/?*
2021/08/31 10:20:44 [3993559] .d..t...... var/lib/icinga2/
2021/08/31 10:20:44 [3993559] >f.st...... var/lib/icinga2/icinga2.state
2021/08/31 10:20:44 [3993559] >f..t...... var/lib/icinga2/modified-attributes.conf
2021/08/31 10:20:44 [3993559] >f.st...... var/lib/influxdb/wal/_internal/monitor/384/_00067.wal
2021/08/31 10:20:44 [3993559] >f.st...... var/lib/influxdb/wal/icinga2/autogen/382/_00002.wal
2021/08/31 10:20:44 [3993559] .d..t...... var/lib/influxdb/wal/proxmox/autogen/381/
2021/08/31 10:20:44 [3993559] >f..t...... var/lib/influxdb/wal/proxmox/autogen/381/_00094.wal
2021/08/31 10:20:44 [3993559] >f+++++++++ var/lib/influxdb/wal/proxmox/autogen/381/_00095.wal
2021/08/31 10:20:44 [3993559] .d..t...... var/lib/influxdb/wal/proxmox2/autogen/383/
2021/08/31 10:20:44 [3993559] >f..t...... var/lib/influxdb/wal/proxmox2/autogen/383/_00151.wal
2021/08/31 10:20:44 [3993559] >f+++++++++ var/lib/influxdb/wal/proxmox2/autogen/383/_00152.wal
2021/08/31 10:20:44 [3993559] >f..t...... var/lib/mysql/ib_logfile0
2021/08/31 10:20:44 [3993559] >f..t...... var/lib/mysql/ibdata1
2021/08/31 10:20:44 [3993559] >f..t...... var/lib/mysql/ibtmp1
2021/08/31 10:20:44 [3993559] >f..t...... var/lib/mysql/icinga2/icinga_hoststatus.ibd
2021/08/31 10:20:44 [3993559] >f..t...... var/lib/mysql/icinga2/icinga_programstatus.ibd
2021/08/31 10:20:44 [3993559] >f..t...... var/lib/mysql/icinga2/icinga_runtimevariables.ibd
2021/08/31 10:20:44 [3993559] >f..t...... var/lib/mysql/icinga2/icinga_servicestatus.ibd
2021/08/31 10:20:45 [3993559] >f..t...... var/lib/mysql/icinga2/icinga_statehistory.ibd
2021/08/31 10:20:45 [3993559] >f..t...... var/lib/mysql/mysql/innodb_index_stats.ibd
2021/08/31 10:20:45 [3993559] >f..t...... var/lib/mysql/mysql/innodb_table_stats.ibd
2021/08/31 10:20:45 [3993559] [sender] hiding directory var/tmp/systemd-private-f715f1c95d39480aa210ced54c3381ea-apache2.service-libx8V because of pattern /var/tmp/?*
2021/08/31 10:20:45 [3993559] [sender] hiding directory var/tmp/systemd-private-f715f1c95d39480aa210ced54c3381ea-systemd-resolved.service-bQuNDc because of pattern /var/tmp/?*
2021/08/31 10:20:45 [3993559] >f..t...... var/lib/php/sessions/sess_upp9omc1i4c3qoep26kko4gjb4
2021/08/31 10:20:45 [3993559] >f.st...... var/log/syslog
2021/08/31 10:20:45 [3993559] >f.st...... var/log/apache2/access.log
2021/08/31 10:20:45 [3993559] >f..t...... var/log/journal/5311003402dc4478b04f0b6410e0ab23/system.journal
 
Last edited:
In Bullseye-based systems, the default value of the 'fs.protected_regular' sysctl is changed to '2' from the previous value of '0'. This adjustment creates a challenge for rsync's --inplace mode as it restricts the root user from opening protected files with O_CREAT.

An instance highlighting this problem can be seen in Debian (or Debian-based) containers that employ PHP. These containers often have a session directory located at '/var/lib/php/sessions' which possesses sticky permissions, is accessible to all users, owned by root, and stores session files typically owned by www-data. If any of these session files are altered between the initial and subsequent rsync operations, the second run and consequently the backup process will encounter errors.

To resolve this issue, it is recommended to set the 'fs.protected_regular' value in Proxmox before backing up the LXC container, or alternatively, make the modification permanent by adding the following line to the '/etc/sysctl.conf' file:

# sysctl fs.protected_regular=0

Reference
 

About

The Proxmox community has been around for many years and offers help and support for Proxmox VE, Proxmox Backup Server, and Proxmox Mail Gateway.
We think our community is one of the best thanks to people like you!

Get your subscription!

The Proxmox team works very hard to make sure you are running the best software and getting stable updates and security enhancements, as well as quick enterprise support. Tens of thousands of happy customers have a Proxmox subscription. Get yours easily in our online shop.

Buy now!