[SOLVED] Backup error occurs after enabling "Protected" checkbox

[linum]

Starting a backup within the proxmox ui to a pbs storage and enabling the "Proctected" checkbox I get the following error:

INFO: backup is sparse: 216.12 GiB (84%) total zero data
INFO: backup was done incrementally, reused 234.97 GiB (91%)
INFO: transferred 256.00 GiB in 222 seconds (1.2 GiB/s)
INFO: stopping kvm after backup task
INFO: adding notes to backup
INFO: marking backup as protected
ERROR: Backup of VM 89001 failed - unable to set protected flag - 400 Bad Request
INFO: Failed at 2022-10-13 08:38:23
INFO: Backup job finished with errors
TASK ERROR: job errors

The backup user has DatastoreAdmin rights, the pbs is a version 2.2.7-1 and the pve server pve-manager/7.2-11/b76d3178. I tried to fied to log at the pbs server but I wasn't able to locate the file...

proxmox-backup-manager versions
proxmox-backup-server 2.2.7-1 running version: 2.2.7

pveversion
pve-manager/7.2-11/b76d3178 (running kernel: 5.15.60-2-pve)

 

[datschlatscher]

Hi,

Are there any messages that occur in the system logs of either machine that might be of interest? You can check with journalctl. Please feel free to post them here.

 

[linum]

Ok, I made a new backup and get these logs:

INFO: starting new backup job: vzdump 83010 --storage horst --notes-template '{{guestname}}' --mode stop --protected 1 --remove 0 --node hugo
INFO: Starting Backup of VM 83010 (qemu)
INFO: Backup started at 2022-10-13 13:21:14
INFO: status = stopped
INFO: backup mode: stop
INFO: ionice priority: 7
INFO: VM Name: sauron
INFO: include disk 'scsi0' 'nvm01:vm-83010-disk-0' 128G
INFO: snapshots found (not included into backup)
INFO: creating Proxmox Backup Server archive 'vm/83010/2022-10-13T11:21:14Z'
INFO: starting kvm to execute backup task
INFO: enabling encryption
INFO: started backup task '66fe6b97-3d93-4f6e-99fc-27db93c9d3e8'
INFO: scsi0: dirty-bitmap status: created new
INFO:   1% (1.6 GiB of 128.0 GiB) in 3s, read: 557.3 MiB/s, write: 0 B/s
INFO:   2% (2.9 GiB of 128.0 GiB) in 6s, read: 444.0 MiB/s, write: 0 B/s
INFO:   3% (4.2 GiB of 128.0 GiB) in 9s, read: 434.7 MiB/s, write: 0 B/s
INFO:   4% (5.5 GiB of 128.0 GiB) in 12s, read: 440.0 MiB/s, write: 0 B/s
INFO:   5% (6.8 GiB of 128.0 GiB) in 15s, read: 445.3 MiB/s, write: 0 B/s
INFO:   6% (8.1 GiB of 128.0 GiB) in 18s, read: 438.7 MiB/s, write: 0 B/s
INFO:   7% (9.4 GiB of 128.0 GiB) in 21s, read: 441.3 MiB/s, write: 0 B/s
INFO:   8% (10.6 GiB of 128.0 GiB) in 24s, read: 430.7 MiB/s, write: 0 B/s
INFO:   9% (11.9 GiB of 128.0 GiB) in 27s, read: 428.0 MiB/s, write: 0 B/s
INFO:  10% (13.2 GiB of 128.0 GiB) in 30s, read: 433.3 MiB/s, write: 0 B/s
INFO:  11% (14.4 GiB of 128.0 GiB) in 33s, read: 421.3 MiB/s, write: 0 B/s
INFO:  12% (15.8 GiB of 128.0 GiB) in 36s, read: 461.3 MiB/s, write: 0 B/s
INFO:  13% (17.1 GiB of 128.0 GiB) in 39s, read: 472.0 MiB/s, write: 0 B/s
INFO:  14% (18.4 GiB of 128.0 GiB) in 42s, read: 437.3 MiB/s, write: 0 B/s
INFO:  15% (19.7 GiB of 128.0 GiB) in 45s, read: 445.3 MiB/s, write: 0 B/s
INFO:  16% (21.1 GiB of 128.0 GiB) in 48s, read: 464.0 MiB/s, write: 0 B/s
INFO:  17% (22.5 GiB of 128.0 GiB) in 51s, read: 470.7 MiB/s, write: 0 B/s
INFO:  18% (23.8 GiB of 128.0 GiB) in 54s, read: 464.0 MiB/s, write: 0 B/s
INFO:  19% (25.4 GiB of 128.0 GiB) in 57s, read: 532.0 MiB/s, write: 0 B/s
INFO:  20% (26.8 GiB of 128.0 GiB) in 1m, read: 494.7 MiB/s, write: 0 B/s
INFO:  22% (28.5 GiB of 128.0 GiB) in 1m 3s, read: 581.3 MiB/s, write: 0 B/s
INFO:  23% (30.2 GiB of 128.0 GiB) in 1m 6s, read: 569.3 MiB/s, write: 0 B/s
INFO:  25% (32.0 GiB of 128.0 GiB) in 1m 9s, read: 629.3 MiB/s, write: 0 B/s
INFO:  27% (34.6 GiB of 128.0 GiB) in 1m 12s, read: 882.7 MiB/s, write: 0 B/s
INFO:  29% (37.5 GiB of 128.0 GiB) in 1m 15s, read: 992.0 MiB/s, write: 0 B/s
INFO:  31% (40.2 GiB of 128.0 GiB) in 1m 18s, read: 928.0 MiB/s, write: 0 B/s
INFO:  33% (42.8 GiB of 128.0 GiB) in 1m 21s, read: 870.7 MiB/s, write: 0 B/s
INFO:  37% (48.6 GiB of 128.0 GiB) in 1m 24s, read: 1.9 GiB/s, write: 0 B/s
INFO:  45% (58.2 GiB of 128.0 GiB) in 1m 27s, read: 3.2 GiB/s, write: 0 B/s
INFO:  52% (67.4 GiB of 128.0 GiB) in 1m 30s, read: 3.1 GiB/s, write: 0 B/s
INFO:  60% (76.9 GiB of 128.0 GiB) in 1m 33s, read: 3.2 GiB/s, write: 0 B/s
INFO:  67% (86.2 GiB of 128.0 GiB) in 1m 36s, read: 3.1 GiB/s, write: 0 B/s
INFO:  74% (95.5 GiB of 128.0 GiB) in 1m 39s, read: 3.1 GiB/s, write: 0 B/s
INFO:  81% (104.4 GiB of 128.0 GiB) in 1m 42s, read: 3.0 GiB/s, write: 0 B/s
INFO:  88% (113.3 GiB of 128.0 GiB) in 1m 45s, read: 3.0 GiB/s, write: 0 B/s
INFO:  95% (121.7 GiB of 128.0 GiB) in 1m 48s, read: 2.8 GiB/s, write: 0 B/s
INFO: 100% (128.0 GiB of 128.0 GiB) in 1m 51s, read: 2.1 GiB/s, write: 0 B/s
INFO: backup is sparse: 93.91 GiB (73%) total zero data
INFO: backup was done incrementally, reused 128.00 GiB (100%)
INFO: transferred 128.00 GiB in 111 seconds (1.2 GiB/s)
INFO: stopping kvm after backup task
INFO: adding notes to backup
INFO: marking backup as protected
ERROR: Backup of VM 83010 failed - unable to set protected flag - 400 Bad Request
INFO: Failed at 2022-10-13 13:23:08
INFO: Backup job finished with errors
TASK ERROR: job errors

and

Oct 13 13:14:49 horst proxmox-backup-proxy[8649]: starting new backup on datastore 'pbs01': "vm/83010/2022-10-13T11:14:49Z"
Oct 13 13:14:49 horst proxmox-backup-proxy[8649]: created new fixed index 1 ("vm/83010/2022-10-13T11:14:49Z/drive-scsi0.img.fidx")
Oct 13 13:14:50 horst proxmox-backup-proxy[8649]: add blob "/pbs01/vm/83010/2022-10-13T11:14:49Z/qemu-server.conf.blob" (380 bytes, comp: 380)
Oct 13 13:17:03 horst proxmox-backup-proxy[8649]: error during snapshot file listing: 'unable to load blob '"/pbs01/vm/83010/2022-10-13T11:14:49Z/index.json.blob"' - No such file or directory (os error 2)'
Oct 13 13:17:33 horst proxmox-backup-proxy[8649]: add blob "/pbs01/vm/83010/2022-10-13T11:14:49Z/index.json.blob" (443 bytes, comp: 443)
Oct 13 13:17:35 horst proxmox-backup-proxy[8649]: PUT /api2/json/admin/datastore/pbs01/protected: 400 Bad Request: [client [::ffff:192.168.81.40]:59782] unable to acquire lock on snapshot directory "/pbs01/vm/83010/2022-10-13T11:14:49Z" - possibly running or in use
Oct 13 13:21:15 horst proxmox-backup-proxy[8649]: starting new backup on datastore 'pbs01': "vm/83010/2022-10-13T11:21:14Z"
Oct 13 13:21:15 horst proxmox-backup-proxy[8649]: created new fixed index 1 ("vm/83010/2022-10-13T11:21:14Z/drive-scsi0.img.fidx")
Oct 13 13:21:15 horst proxmox-backup-proxy[8649]: add blob "/pbs01/vm/83010/2022-10-13T11:21:14Z/qemu-server.conf.blob" (374 bytes, comp: 374)
Oct 13 13:23:05 horst proxmox-backup-proxy[8649]: add blob "/pbs01/vm/83010/2022-10-13T11:21:14Z/index.json.blob" (443 bytes, comp: 443)
Oct 13 13:23:08 horst proxmox-backup-proxy[8649]: PUT /api2/json/admin/datastore/pbs01/protected: 400 Bad Request: [client [::ffff:192.168.81.40]:46990] unable to acquire lock on snapshot directory "/pbs01/vm/83010/2022-10-13T11:21:14Z" - possibly running or in use

 

[datschlatscher]

Do you have the option "Verify New" in your datastore set to true? I just tested this and there seems to be a problem where the verify will aquire a lock before the protected status of the backup can be set. That's why it always fails with an error.

If that is the case here as well, you would have to either set the protected status after the verify job has finished or turn off automatic verification and run the verification at some other time. That is, until a fix is packaged, of course.

 

[linum]

You're right, the option "Verify new snapshots" is set to "Yes". And I already made a new test backup with the "Protected" Checkbox to "Yes" without an error.

I think it should work nevertheless the "Verify new snapshots" at the server...

Thanks for the help!

 

[fireon]

Is there any bugreport for this?

 

[fiona]

Is there any bugreport for this?

Yes: https://bugzilla.proxmox.com/show_bug.cgi?id=4289