For all of my VMs, backups always succeed.
For some of them however, the result is bad:
they fail verification
the first stored disk cannot be downloaded, the http response is:
unable to read fixed index <filename> - Unable to open fixed index <filename> - got unknown magic number
of course, the file restire function also gives an error:
Starting VM failed. See output above for more information. (500)
I failed to find any further information in the logs (or in the response).
The error does occur for some of the vms, and even then, not completely consistently. The only common thing about them is that all such VMs have at least two disks.
Other observations:
Repeated backups after a bad result usually (but not always) also create a bad result.
Repeated backups after a good result (even if there was a bad result before that) usually (but not always) also create a good result.
Migrating a VM to another node and then doing a new backup sometimes creates a good result.
Setting up replication (and waiting for it to finish) for a VM and then doing a new backup usually creates a good result.
I cannot give a complete report yet as re-doing backups takes about 20minutes + 60minutes of verification (the VMs are about 200GiB, there were some smaller ones but they decided to fix themselves after a manual test backup and are producing good backups ever since :/ ), .
Has anyone seen something similar?
If yes, what may be the problem?
If no, does anyone know how to debug a backup or verification process?
please post the output of od --format=u1 --read-bytes=8 /mnt/backup-cephfs/ns/backup/vm/440/2024-06-19T10\:32\:19Z/drive-virtio0.img.fidx
The output should match exactly 0000000 47 127 65 237 145 253 15 205
if not (and it seems like) your fixed index is currupted or something else than a fixed index. the magic number is a 8-byte long identifier of the file type.
Does the time stamp of your fixed index match the date/time when the backup was created?
if not (and it seems like) your fixed index is currupted or something else than a fixed index. the magic number is a 8-byte long identifier of the file type.
Update: I ran a lot of new backups, and observed the happenings in the backup metadata directory with the following script:
Code:
while sleep 10; do for i in 0 1 ; do od --format=u
1 drive-virtio$i*fidx| head -n1 ; od --format=u1 drive-virtio$i*fidx| wc -l ; done; done
This prints the first 16 bytes (which contain the magic number) and the approximate number of non-zero 16-byte chunks for both fidx files every 10 seconds.
In the beginning, both drive-virtio0.img.tmp_fidx and drive-virtio1.img.tmp_fidx were created, with a good magic number and not much else (qemu-server.conf.blob was also created, but that is not relevant):
Then drive-virtio1.img.tmp_fidx was being filled up with non-zeroes as virtio1 was being backed up according to the server job log, roughly the same percent being non-zero as the disk's completion according to the log. The output is like this:
Then at the end, drive-virtio0.img.tmp_fidx is filled up with data. Unfortunately, both of my bad-backup VMs decided that they backup nicely if I observe them (Scrödinger's backup ). I will continue to try to reproduce the error while observing...
Hi,
please provide the output of pveversion -v for the Proxmox VE nodes and the proxmox-backup-manager versions --verbose of the Proxmox Backup Server host.
These intermitten type of errors might indicate an underlying hardware issue. So please also check the disks health of those backing the storage on the PBS side as well as the system memory by performing a prolonged memory test. What storage disks are you using?
Hi,
please provide the output of pveversion -v for the Proxmox VE nodes and the proxmox-backup-manager versions --verbose of the Proxmox Backup Server host.
These intermitten type of errors might indicate an underlying hardware issue. So please also check the disks health of those backing the storage on the PBS side as well as the system memory by performing a prolonged memory test. What storage disks are you using?
Hardware failure is quite possible, though disk failure is unlikely, as data is on a ceph cluster with 6+4 redundancy, and I recently replaced the memory (increased it, which required replacement; but of course the "new" memory could still be bad) and run some memory testing, but only on-line so far.
I could still be CPU/motherboard failure or ceph or other software failure.
There were some errors since the memory replacement, but I could not pin them down, and could not reproduce them either yet. I extended my watcher script to detect new backups and monitor and log the fidx files' state, so maybe I will be able to catch the error later.
Hardware failure is quite possible, though disk failure is unlikely, as data is on a ceph cluster with 6+4 redundancy, and I recently replaced the memory (increased it, which required replacement; but of course the "new" memory could still be bad) and run some memory testing, but only on-line so far.
I could still be CPU/motherboard failure or ceph or other software failure.
There were some errors since the memory replacement, but I could not pin them down, and could not reproduce them either yet. I extended my watcher script to detect new backups and monitor and log the fidx files' state, so maybe I will be able to catch the error later.
Well, the cluster consists of a single machine (for now, this was supposed to be a proof-of-concept that could be expanded later), with 12 4TB HDDs and 2 100GB SSDs for system.
# devices
device 0 osd.0 class hdd
device 1 osd.1 class hdd
device 2 osd.2 class hdd
device 3 osd.3 class hdd
device 4 osd.4 class hdd
device 5 osd.5 class hdd
device 6 osd.6 class hdd
device 7 osd.7 class hdd
device 8 osd.8 class hdd
device 9 osd.9 class hdd
device 10 osd.10 class hdd
device 11 osd.11 class hdd
# types
type 0 osd
type 1 host
type 2 chassis
type 3 rack
type 4 row
type 5 pdu
type 6 pod
type 7 room
type 8 datacenter
type 9 zone
type 10 region
type 11 root
# buckets
host pvebackup {
id -3 # do not change unnecessarily
id -4 class hdd # do not change unnecessarily
# weight 0.00000
alg straw2
hash 0 # rjenkins1
}
host pvebackup1 {
id -5 # do not change unnecessarily
id -6 class hdd # do not change unnecessarily
# weight 43.65839
alg straw2
hash 0 # rjenkins1
item osd.1 weight 3.63820
item osd.0 weight 3.63820
item osd.2 weight 3.63820
item osd.3 weight 3.63820
item osd.5 weight 3.63820
item osd.6 weight 3.63820
item osd.7 weight 3.63820
item osd.8 weight 3.63820
item osd.9 weight 3.63820
item osd.10 weight 3.63820
item osd.11 weight 3.63820
item osd.4 weight 3.63820
}
root default {
id -1 # do not change unnecessarily
id -2 class hdd # do not change unnecessarily
# weight 43.65839
alg straw2
hash 0 # rjenkins1
item pvebackup weight 0.00000
item pvebackup1 weight 43.65839
}
# rules
rule replicated_rule {
id 0
type replicated
step take default
step chooseleaf firstn 0 type host
step emit
}
rule ecpool {
id 1
type erasure
step set_chooseleaf_tries 5
step set_choose_tries 100
step take default
step chooseleaf indep 0 type host
step emit
}
rule replicated_rule_osd {
id 2
type replicated
step take default
step choose firstn 0 type osd
step emit
}
rule 10_4_ecpool {
id 3
type erasure
step set_chooseleaf_tries 5
step set_choose_tries 100
step take default
step choose indep 0 type osd
step emit
}
Well, the cluster consists of a single machine (for now, this was supposed to be a proof-of-concept that could be expanded later), with 12 4TB HDDs and 2 100GB SSDs for system.
# devices
device 0 osd.0 class hdd
device 1 osd.1 class hdd
device 2 osd.2 class hdd
device 3 osd.3 class hdd
device 4 osd.4 class hdd
device 5 osd.5 class hdd
device 6 osd.6 class hdd
device 7 osd.7 class hdd
device 8 osd.8 class hdd
device 9 osd.9 class hdd
device 10 osd.10 class hdd
device 11 osd.11 class hdd
# types
type 0 osd
type 1 host
type 2 chassis
type 3 rack
type 4 row
type 5 pdu
type 6 pod
type 7 room
type 8 datacenter
type 9 zone
type 10 region
type 11 root
# buckets
host pvebackup {
id -3 # do not change unnecessarily
id -4 class hdd # do not change unnecessarily
# weight 0.00000
alg straw2
hash 0 # rjenkins1
}
host pvebackup1 {
id -5 # do not change unnecessarily
id -6 class hdd # do not change unnecessarily
# weight 43.65839
alg straw2
hash 0 # rjenkins1
item osd.1 weight 3.63820
item osd.0 weight 3.63820
item osd.2 weight 3.63820
item osd.3 weight 3.63820
item osd.5 weight 3.63820
item osd.6 weight 3.63820
item osd.7 weight 3.63820
item osd.8 weight 3.63820
item osd.9 weight 3.63820
item osd.10 weight 3.63820
item osd.11 weight 3.63820
item osd.4 weight 3.63820
}
root default {
id -1 # do not change unnecessarily
id -2 class hdd # do not change unnecessarily
# weight 43.65839
alg straw2
hash 0 # rjenkins1
item pvebackup weight 0.00000
item pvebackup1 weight 43.65839
}
# rules
rule replicated_rule {
id 0
type replicated
step take default
step chooseleaf firstn 0 type host
step emit
}
rule ecpool {
id 1
type erasure
step set_chooseleaf_tries 5
step set_choose_tries 100
step take default
step chooseleaf indep 0 type host
step emit
}
rule replicated_rule_osd {
id 2
type replicated
step take default
step choose firstn 0 type osd
step emit
}
rule 10_4_ecpool {
id 3
type erasure
step set_chooseleaf_tries 5
step set_choose_tries 100
step take default
step choose indep 0 type osd
step emit
}
It recurred again, but I again could not reproduce the bug while observing. Truly a quantum bug.
It very well may be a cephfs problem, I will move the fidx files to another file system to rule that out. The stange thing is that the chunk files do not produce such errors (otherwise verifications would fail I assume).
It recurred again, but I again could not reproduce the bug while observing. Truly a quantum bug.
It very well may be a cephfs problem, I will move the fidx files to another file system to rule that out. The stange thing is that the chunk files do not produce such errors (otherwise verifications would fail I assume).
I'm having the same issue, also using kernal based cephfs as a datastore. The issue seems to start on vm's that I have expanded the volumes on. It's inconsistent on some vms, and consistent on a homeassistant vm I have running. Prior to expanding the volume on home assistant backups verified 100% after expanding the volume the backups have failed verification 100%. I'll do a test to see if installing a fresh install of HA doing a backup and then expanding the volume and doing anther backup results in the same behavior.
I'm having the same issue, also using kernal based cephfs as a datastore. The issue seems to start on vm's that I have expanded the volumes on. It's inconsistent on some vms, and consistent on a homeassistant vm I have running. Prior to expanding the volume on home assistant backups verified 100% after expanding the volume the backups have failed verification 100%. I'll do a test to see if installing a fresh install of HA doing a backup and then expanding the volume and doing anther backup results in the same behavior.
Also, please share your Kernel version uname -a as currently running on the PBS host and check if the issue persists when mounting the CephFS via the fuse client. Thanks!
Also, please share your Kernel version uname -a as currently running on the PBS host and check if the issue persists when mounting the CephFS via the fuse client. Thanks!
I tested switching back and forth several times, the kernal based ceph errors on varification evey time, whereas ceph-fuse does not. Verification takes significantly longer using ceph-fuse from 20mins to 80min, but my cluster is running on low power/limited memory hardware. I'll keep using cepf-fuse and see if I run into any other issues.
uname -a Linux pbs 6.8.8-3-pve #1 SMP PREEMPT_DYNAMIC PMX 6.8.8-3 (2024-07-16T16:16Z) x86_64 GNU/Linux
Kernel ceph --------
HexDump
head -c100 /mnt/cephfs/hdd-ceph-fs/proxmox/proxmox-backup-server/vm/200/2024-08-03T00:11:01Z/drive-efidisk0.img.fidx | hexdump
od --format=u1 --read-bytes=8 /mnt/cephfs/hdd-ceph-fs/proxmox/proxmox-backup-server/vm/200/2024-08-03T00:11:01Z/drive-efidisk0.img.fidx
Bash:
0000000 0 0 0 0 0 0 0 0
0000010
systemd journal
No errors for ceph just logs showing the volume mounted. Though I did get a lot of PBS unable to parse worker status
journalctl -e | grep ceph
Bash:
Aug 02 17:09:42 pbs systemd[1]: Reached target ceph.target - ceph target allowing to start/stop all ceph*@.service instances at once.
Aug 02 17:09:49 pbs systemd[1]: Mounting mnt-cephfs-hdd\x2dceph\x2dfs.mount - /mnt/cephfs/hdd-ceph-fs...
Aug 02 17:09:49 pbs kernel: Key type ceph registered
Aug 02 17:09:49 pbs kernel: libceph: loaded (mon/osd proto 15/24)
Aug 02 17:09:49 pbs kernel: ceph: loaded (mds proto 32)
Aug 02 17:09:49 pbs kernel: libceph: mon1 (1)10.10.10.13:6789 session established
Aug 02 17:09:49 pbs kernel: libceph: client83638182 fsid 3e4a2951-1a66-42a9-8767-2d207d6eb310
Aug 02 17:09:51 pbs systemd[1]: Mounted mnt-cephfs-hdd\x2dceph\x2dfs.mount - /mnt/cephfs/hdd-ceph-fs.
Aug 02 17:11:14 pbs proxmox-backup-proxy[587]: add blob "/mnt/cephfs/hdd-ceph-fs/proxmox/proxmox-backup-server/vm/200/2024-08-03T00:11:01Z/qemu-server.conf.blob" (472 bytes, comp: 472)
Aug 02 17:15:01 pbs proxmox-backup-proxy[587]: add blob "/mnt/cephfs/hdd-ceph-fs/proxmox/proxmox-backup-server/vm/200/2024-08-03T00:11:01Z/index.json.blob" (379 bytes, comp: 379)
Bash:
Aug 02 17:33:41 pbs proxmox-backup-proxy[587]: unable to parse worker status 'UPID:pUPID:pbs:00000268:00000DD5:00000050:6690D470:logrotate::root@pam: 6690D471 OK' - unable to pars>
Aug 02 17:33:56 pbs proxmox-backup-proxy[587]: unable to parse worker status 'UPID:pUPID:pbs:00000268:00000DD5:00000050:6690D470:logrotate::root@pam: 6690D471 OK' - unable to pars>
Aug 02 17:34:11 pbs proxmox-backup-proxy[587]: unable to parse worker status 'UPID:pUPID:pbs:00000268:00000DD5:00000050:6690D470:logrotate::root@pam: 6690D471 OK' - unable to pars>
Aug 02 17:34:26 pbs proxmox-backup-proxy[587]: unable to parse worker status 'UPID:pUPID:pbs:00000268:00000DD5:00000050:6690D470:logrotate::root@pam: 6690D471 OK' - unable to pars>
Aug 02 17:34:41 pbs proxmox-backup-proxy[587]: unable to parse worker status 'UPID:pUPID:pbs:00000268:00000DD5:00000050:6690D470:logrotate::root@pam: 6690D471 OK' - unable to pars>
Aug 02 17:34:57 pbs proxmox-backup-proxy[587]: unable to parse worker status 'UPID:pUPID:pbs:00000268:00000DD5:00000050:6690D470:logrotate::root@pam: 6690D471 OK' - unable to pars>
Aug 02 17:35:12 pbs proxmox-backup-proxy[587]: unable to parse worker status 'UPID:pUPID:pbs:00000268:00000DD5:00000050:6690D470:logrotate::root@pam: 6690D471 OK' - unable to pars>
Aug 02 17:35:27 pbs proxmox-backup-proxy[587]: unable to parse worker status 'UPID:pUPID:pbs:00000268:00000DD5:00000050:6690D470:logrotate::root@pam: 6690D471 OK' - unable to pars>
Aug 02 17:35:42 pbs proxmox-backup-proxy[587]: unable to parse worker status 'UPID:pUPID:pbs:00000268:00000DD5:00000050:6690D470:logrotate::root@pam: 6690D471 OK' - unable to pars>
Aug 02 17:35:57 pbs proxmox-backup-proxy[587]: unable to parse worker status 'UPID:pUPID:pbs:00000268:00000DD5:00000050:6690D470:logrotate::root@pam: 6690D471 OK' - unable to pars>
Aug 02 17:36:18 pbs proxmox-backup-proxy[587]: unable to parse worker status 'UPID:pUPID:pbs:00000268:00000DD5:00000050:6690D470:logrotate::root@pam: 6690D471 OK' - unable to pars>
Aug 02 17:36:38 pbs login[941]: pam_unix(login:session): session opened for user root(uid=0) by root(uid=0)
Backup Job Proxmox
Bash:
INFO: starting new backup job: vzdump 200 --notes-template '{{guestname}}' --mode snapshot --storage proxmox-backup-server --node proxmox01 --notification-mode auto --remove 0
INFO: Starting Backup of VM 200 (qemu)
INFO: Backup started at 2024-08-02 17:11:01
INFO: status = running
INFO: VM Name: HomeAssistant
INFO: include disk 'scsi0' 'ceph-replicated:vm-200-disk-1' 40G
INFO: include disk 'efidisk0' 'ceph-replicated:vm-200-disk-2' 1M
INFO: backup mode: snapshot
INFO: ionice priority: 7
INFO: skip unused drive 'ceph-replicated:vm-200-disk-0' (not included into backup)
INFO: creating Proxmox Backup Server archive 'vm/200/2024-08-03T00:11:01Z'
INFO: issuing guest-agent 'fs-freeze' command
INFO: issuing guest-agent 'fs-thaw' command
ERROR: VM 200 qmp command 'guest-fsfreeze-thaw' failed - got timeout
INFO: started backup task '95a4b67b-d73a-493e-b82a-c08422bd2d4a'
INFO: resuming VM again
INFO: efidisk0: dirty-bitmap status: existing bitmap was invalid and has been cleared
INFO: scsi0: dirty-bitmap status: existing bitmap was invalid and has been cleared
INFO: 100% (40.0 GiB of 40.0 GiB) in 48s, read: 64.8 MiB/s, write: 64.8 MiB/s
INFO: backup is sparse: 12.39 GiB (30%) total zero data
INFO: backup was done incrementally, reused 12.68 GiB (31%)
INFO: transferred 40.00 GiB in 48 seconds (853.3 MiB/s)
INFO: adding notes to backup
INFO: Finished Backup of VM 200 (00:04:01)
INFO: Backup finished at 2024-08-02 17:15:02
INFO: Backup job finished successfully
INFO: notified via target `mail-to-root`
TASK OK
Backup Job PBS
Bash:
2024-08-02T17:11:14-07:00: starting new backup on datastore 'backups' from ::ffff:10.10.10.12: "vm/200/2024-08-03T00:11:01Z"
2024-08-02T17:11:14-07:00: GET /previous: 400 Bad Request: no valid previous backup
2024-08-02T17:11:14-07:00: created new fixed index 1 ("vm/200/2024-08-03T00:11:01Z/drive-efidisk0.img.fidx")
2024-08-02T17:11:14-07:00: created new fixed index 2 ("vm/200/2024-08-03T00:11:01Z/drive-scsi0.img.fidx")
2024-08-02T17:11:14-07:00: add blob "/mnt/cephfs/hdd-ceph-fs/proxmox/proxmox-backup-server/vm/200/2024-08-03T00:11:01Z/qemu-server.conf.blob" (472 bytes, comp: 472)
2024-08-02T17:15:01-07:00: Upload statistics for 'drive-scsi0.img.fidx'
2024-08-02T17:15:01-07:00: UUID: d0fbd2ac375a47329f24f469df9d061a
2024-08-02T17:15:01-07:00: Checksum: 22c66c0c914bfbf992b355db884919652648955692d847e635d81cf5bfa8a41c
2024-08-02T17:15:01-07:00: Size: 42949672960
2024-08-02T17:15:01-07:00: Chunk count: 10240
2024-08-02T17:15:01-07:00: Upload size: 29343350784 (68%)
2024-08-02T17:15:01-07:00: Duplicates: 3244+6702 (97%)
2024-08-02T17:15:01-07:00: Compression: 39%
2024-08-02T17:15:01-07:00: successfully closed fixed index 2
2024-08-02T17:15:01-07:00: Upload statistics for 'drive-efidisk0.img.fidx'
2024-08-02T17:15:01-07:00: UUID: 880cfa6ccc6f4826af60531cf443ef45
2024-08-02T17:15:01-07:00: Checksum: c23bad6e0d1cdf2b6394c3ac802c8c81244ae8bb62c80b1b937ad95b3c988de5
2024-08-02T17:15:01-07:00: Size: 540672
2024-08-02T17:15:01-07:00: Chunk count: 1
2024-08-02T17:15:01-07:00: Upload size: 4734976 (875%)
2024-08-02T17:15:01-07:00: Duplicates: 0+2 (200%)
2024-08-02T17:15:01-07:00: Compression: 0%
2024-08-02T17:15:01-07:00: successfully closed fixed index 1
2024-08-02T17:15:01-07:00: add blob "/mnt/cephfs/hdd-ceph-fs/proxmox/proxmox-backup-server/vm/200/2024-08-03T00:11:01Z/index.json.blob" (379 bytes, comp: 379)
2024-08-02T17:15:01-07:00: successfully finished backup
2024-08-02T17:15:01-07:00: backup finished successfully
2024-08-02T17:15:01-07:00: TASK OK
Verify
Bash:
2024-08-02T17:22:45-07:00: verify backups:vm/200/2024-08-03T00:11:01Z
2024-08-02T17:22:45-07:00: check qemu-server.conf.blob
2024-08-02T17:22:45-07:00: check drive-scsi0.img.fidx
2024-08-02T17:34:57-07:00: verified 11082.30/28312.00 MiB in 731.73 seconds, speed 15.15/38.69 MiB/s (0 errors)
2024-08-02T17:34:57-07:00: check drive-efidisk0.img.fidx
2024-08-02T17:34:57-07:00: verify backups:vm/200/2024-08-03T00:11:01Z/drive-efidisk0.img.fidx failed: Unable to open fixed index "/mnt/cephfs/hdd-ceph-fs/proxmox/proxmox-backup-server/vm/200/2024-08-03T00:11:01Z/drive-efidisk0.img.fidx" - got unknown magic number
2024-08-02T17:34:57-07:00: Failed to verify the following snapshots/groups:
2024-08-02T17:34:57-07:00: vm/200/2024-08-03T00:11:01Z
2024-08-02T17:34:57-07:00: TASK ERROR: verification failed - please check the log for details
Using ceph-fuse ------
HexDump
head -c100 /mnt/cephfs/hdd-ceph-fs/proxmox/proxmox-backup-server/vm/200/2024-08-03T00\:56\:18Z/drive-efidisk0.img.fidx | hexdump
od --format=u1 --read-bytes=8 /mnt/cephfs/hdd-ceph-fs/proxmox/proxmox-backup-server/vm/200/2024-08-03T00\:56\:18Z/drive-efidisk0.img.fidx
Code:
0000000 47 127 65 237 145 253 15 205
0000010
journalctl -e | grep ceph
Code:
Aug 02 17:53:03 pbs systemd[1]: Reached target ceph-fuse.target - ceph target allowing to start/stop all ceph-fuse@.service instances at once.
Aug 02 17:53:03 pbs systemd[1]: Reached target ceph.target - ceph target allowing to start/stop all ceph*@.service instances at once.
Aug 02 17:53:09 pbs systemd[1]: Mounting mnt-cephfs-hdd\x2dceph\x2dfs.mount - /mnt/cephfs/hdd-ceph-fs...
Aug 02 17:53:10 pbs mount[590]: ceph-fuse[590]: starting ceph client
Aug 02 17:53:10 pbs proxmox-backup-proxy[555]: read fs info on "/mnt/cephfs/hdd-ceph-fs/proxmox/proxmox-backup-server" failed - ENOENT: No such file or directory
Aug 02 17:53:10 pbs mount[590]: ceph-fuse[590]: starting fuse
Aug 02 17:53:10 pbs systemd[1]: Mounted mnt-cephfs-hdd\x2dceph\x2dfs.mount - /mnt/cephfs/hdd-ceph-fs.
Bash:
Aug 02 17:59:58 pbs proxmox-backup-proxy[555]: unable to parse worker status 'UPID:pUPID:pbs:00000268:00000DD5:00000050:6690D470:logrotate::root@pam: 6690D471 OK' - unable to parse UPID 'UPID:pUPID:pbs:00000268:00000DD5:00000050:6690D470:logrotate::root@pam:'
Backup Job Proxmox
Bash:
INFO: starting new backup job: vzdump 200 --remove 0 --notification-mode auto --node proxmox01 --notes-template '{{guestname}}' --mode snapshot --storage proxmox-backup-server
INFO: Starting Backup of VM 200 (qemu)
INFO: Backup started at 2024-08-02 17:56:18
INFO: status = running
INFO: VM Name: HomeAssistant
INFO: include disk 'scsi0' 'ceph-replicated:vm-200-disk-1' 40G
INFO: include disk 'efidisk0' 'ceph-replicated:vm-200-disk-2' 1M
INFO: backup mode: snapshot
INFO: ionice priority: 7
INFO: skip unused drive 'ceph-replicated:vm-200-disk-0' (not included into backup)
INFO: creating Proxmox Backup Server archive 'vm/200/2024-08-03T00:56:18Z'
INFO: issuing guest-agent 'fs-freeze' command
INFO: issuing guest-agent 'fs-thaw' command
INFO: started backup task '1e507365-31bc-4863-aa30-8f70b0bbd466'
INFO: resuming VM again
INFO: efidisk0: dirty-bitmap status: existing bitmap was invalid and has been cleared
INFO: scsi0: dirty-bitmap status: existing bitmap was invalid and has been cleared
INFO: 100% (40.0 GiB of 40.0 GiB) in 6m 15s, read: 71.3 MiB/s, write: 71.3 MiB/s
INFO: backup is sparse: 12.39 GiB (30%) total zero data
INFO: backup was done incrementally, reused 12.66 GiB (31%)
INFO: transferred 40.00 GiB in 376 seconds (108.9 MiB/s)
INFO: adding notes to backup
INFO: Finished Backup of VM 200 (00:06:25)
INFO: Backup finished at 2024-08-02 18:02:43
INFO: Backup job finished successfully
INFO: notified via target `mail-to-root`
TASK OK
Backup Job PBS
Code:
2024-08-02T17:56:20-07:00: starting new backup on datastore 'backups' from ::ffff:10.10.10.12: "vm/200/2024-08-03T00:56:18Z"
2024-08-02T17:56:20-07:00: GET /previous: 400 Bad Request: no valid previous backup
2024-08-02T17:56:20-07:00: created new fixed index 1 ("vm/200/2024-08-03T00:56:18Z/drive-efidisk0.img.fidx")
2024-08-02T17:56:20-07:00: created new fixed index 2 ("vm/200/2024-08-03T00:56:18Z/drive-scsi0.img.fidx")
2024-08-02T17:56:20-07:00: add blob "/mnt/cephfs/hdd-ceph-fs/proxmox/proxmox-backup-server/vm/200/2024-08-03T00:56:18Z/qemu-server.conf.blob" (472 bytes, comp: 472)
2024-08-02T18:02:42-07:00: Upload statistics for 'drive-scsi0.img.fidx'
2024-08-02T18:02:42-07:00: UUID: e357b7ffd0174a7b977193e61007214b
2024-08-02T18:02:42-07:00: Checksum: ab1261730c4f822a10d7ef147c88fa54e135b71147681f58a7bd1cc6b8bcc938
2024-08-02T18:02:42-07:00: Size: 42949672960
2024-08-02T18:02:42-07:00: Chunk count: 10240
2024-08-02T18:02:42-07:00: Upload size: 29355933696 (68%)
2024-08-02T18:02:42-07:00: Duplicates: 3241+6528 (95%)
2024-08-02T18:02:42-07:00: Compression: 39%
2024-08-02T18:02:42-07:00: successfully closed fixed index 2
2024-08-02T18:02:42-07:00: Upload statistics for 'drive-efidisk0.img.fidx'
2024-08-02T18:02:42-07:00: UUID: 45e85fcca76e4ab4829c0c5cb6af5007
2024-08-02T18:02:42-07:00: Checksum: c23bad6e0d1cdf2b6394c3ac802c8c81244ae8bb62c80b1b937ad95b3c988de5
2024-08-02T18:02:42-07:00: Size: 540672
2024-08-02T18:02:42-07:00: Chunk count: 1
2024-08-02T18:02:42-07:00: Upload size: 4734976 (875%)
2024-08-02T18:02:42-07:00: Duplicates: 0+2 (200%)
2024-08-02T18:02:42-07:00: Compression: 0%
2024-08-02T18:02:42-07:00: successfully closed fixed index 1
2024-08-02T18:02:42-07:00: add blob "/mnt/cephfs/hdd-ceph-fs/proxmox/proxmox-backup-server/vm/200/2024-08-03T00:56:18Z/index.json.blob" (380 bytes, comp: 380)
2024-08-02T18:02:42-07:00: successfully finished backup
2024-08-02T18:02:42-07:00: backup finished successfully
2024-08-02T18:02:42-07:00: TASK OK
Thanks a lot for the feedback, so this now clearly points towards an issue with the in-kernel cephfs client.
If you are willing, please try to debug the issue further by enabling dynamic debugging output. To do this, please use a non production PBS instance with enough free space, as otherwise you might run into issues because of the root disk of the instance running full. Also, there should nothing else interact with the cephfs client, so to get a clean debug trace. Also, if you manage to have a VM with small disks, and therefore reduced backup runtime, that would help limiting the amount of output.
First you should reproduce the issue there, then you can clear the snapshots and enable the dynamic debugging output for ceph and libceph via a small shell script like so
I switched back to kernal ceph this morning and the error is no longer happening. Between the issue happening and now a scheduled garbage collection on PBS ran (the backups with verification issues prevented the garbage collection form completing previously). I'll do some tests and see if I can get it to start failing varification again to get a debug log for you.
I switched back to kernal ceph this morning and the error is no longer happening. Between the issue happening and now a scheduled garbage collection on PBS ran (the backups with verification issues prevented the garbage collection form completing previously). I'll do some tests and see if I can get it to start failing varification again to get a debug log for you.
Thanks, the garbage collection should however be unrelated.
Let me give some more insights on the current hypothesis: The suspicion is that there is a cephfs bug related to caching, making this unfortunately also more difficult to reproduce and debug. This is also why the backup is successful, as checksums and sizes written to disk as seen by the proxmox backup client do match the expected ones, while the underlying filesystem seems to not persist the initial writing of the header, only writing the final bytes when updating the index checksum. This is why the full 4k page is zeroed, except for the checksum written when finishing and closing the fixed index file. Also, so far this seems to only happen with VMs having more than 1 disk attached, which indicates that only a certain sequence of operations and timings leads to this.
So comparing the dynamic debug output of the boguos run with a good run should help to see in the source code where things go wrong.
This site uses cookies to help personalise content, tailor your experience and to keep you logged in if you register.
By continuing to use this site, you are consenting to our use of cookies.
). I will continue to try to reproduce the error while observing...
