New Datastore Presents - WARN: unable to add notes - File exists (os error 17)

[ctrl]

WARN: unable to add notes - proxmox-backup-client failed: Error: unable to update manifest blob - Atomic rename failed for file "/vmbkdata/vm/105/2023-09-30T20:20:06Z/index.json.blob" - File exists (os error 17)

I am having a issue with my PBS where I have created a new datastore and after running fresh backups for the VMS, selectively and not all backups return the error above.

Backup Server 3.0-2
PVE: 8.0.4

While looking at the new datastore VMs which have not failed with this error are intact however the failures above result in a 1 Byte entry on the datastore. Can someone clue me into a direction here or any other information that I can present which may assist.

Thanks

Example Failure

2023-09-30T16:23:41-04:00: starting new backup on datastore 'vmbkdata': "vm/106/2023-09-30T20:23:39Z"
2023-09-30T16:23:41-04:00: GET /previous: 400 Bad Request: no valid previous backup
2023-09-30T16:23:41-04:00: created new fixed index 1 ("vm/106/2023-09-30T20:23:39Z/drive-scsi0.img.fidx")
2023-09-30T16:23:42-04:00: created new fixed index 2 ("vm/106/2023-09-30T20:23:39Z/drive-scsi1.img.fidx")
2023-09-30T16:23:42-04:00: add blob "/vmbkdata/vm/106/2023-09-30T20:23:39Z/qemu-server.conf.blob" (396 bytes, comp: 396)
2023-09-30T16:34:24-04:00: Upload statistics for 'drive-scsi1.img.fidx'
2023-09-30T16:34:24-04:00: UUID: 20a8b7dfb05b4cfdad756209e214118f
2023-09-30T16:34:24-04:00: Checksum: d8e29e6cb56dbce39e61abf92e65a92c897f0dd018cd892a7dec37611d7261fe
2023-09-30T16:34:24-04:00: Size: 32212254720
2023-09-30T16:34:24-04:00: Chunk count: 7680
2023-09-30T16:34:24-04:00: Upload size: 3917479936 (12%)
2023-09-30T16:34:24-04:00: Duplicates: 6746+1 (87%)
2023-09-30T16:34:24-04:00: Compression: 34%
2023-09-30T16:34:24-04:00: successfully closed fixed index 2
2023-09-30T16:34:24-04:00: Upload statistics for 'drive-scsi0.img.fidx'
2023-09-30T16:34:24-04:00: UUID: 027dd5b3fc7c43028683e6efd217a8aa
2023-09-30T16:34:24-04:00: Checksum: fb7d6edc5988cfe1ae44b5f0af73122638e1dccfb629bd37ec622816b58290f7
2023-09-30T16:34:24-04:00: Size: 53687091200
2023-09-30T16:34:24-04:00: Chunk count: 12800
2023-09-30T16:34:24-04:00: Upload size: 40156266496 (74%)
2023-09-30T16:34:24-04:00: Duplicates: 3226+1 (25%)
2023-09-30T16:34:24-04:00: Compression: 62%
2023-09-30T16:34:24-04:00: successfully closed fixed index 1
2023-09-30T16:34:24-04:00: add blob "/vmbkdata/vm/106/2023-09-30T20:23:39Z/index.json.blob" (378 bytes, comp: 378)
2023-09-30T16:34:24-04:00: POST /finish: 400 Bad Request: unable to update manifest blob - Atomic rename failed for file "/vmbkdata/vm/106/2023-09-30T20:23:39Z/index.json.blob" - File exists (os error 17)
2023-09-30T16:34:24-04:00: backup ended and finish failed: backup ended but finished flag is not set.
2023-09-30T16:34:24-04:00: removing unfinished backup
2023-09-30T16:34:24-04:00: TASK ERROR: backup ended but finished flag is not set.

verify vmbkdata:vm/102/2023-10-02T22:14:15Z/drive-virtio0.img.fidx failed: Unable to open fixed index "/vmbkdata/vm/102/2023-10-02T22:14:15Z/drive-virtio0.img.fidx" - Permission denied (os error 13)

drwxr-xr-x     5 backup backup 4.0K Oct  2 18:40 .
drwxr-xr-x    19 backup backup 4.0K Sep 30 15:23 ..
drwxr-x--- 65538 backup backup 4.0K Oct  2 18:06 .chunks
-rw-r--r--     1 backup backup    0 Oct  2 17:54 .lock
drwxr-xr-x     4 backup backup 4.0K Oct  2 18:14 vm

 

[ggoller]

Hi,
this is weird, we do a standard Linux `rename`, and that should never return a "File exists" error. Can you still reproduce this error?
If yes, could you paste the result of a `ls -lah` in `/vmbkdata/vm/106/2023-09-30T20:23:39Z/` (or in the backup dir where the error occurs)?

 

[ctrl]

Hi,
this is weird, we do a standard Linux `rename`, and that should never return a "File exists" error. Can you still reproduce this error?
If yes, could you paste the result of a `ls -lah` in `/vmbkdata/vm/106/2023-09-30T20:23:39Z/` (or in the backup dir where the error occurs)?

Thanks, yes its reproducible. Sometimes VMs will complete, most of the time that error persists its not specific to 1 VM or backup group, all backups are basically broken even though data is being written with some of them.

root@pmbkv01:/vmbkdata/vm/106# pwd
/vmbkdata/vm/106
root@pmbkv01:/vmbkdata/vm/106# ls -lah
total 8.5K
drwxr-xr-x  2 backup backup 4.0K Oct  3 23:00 .
drwxrwxrwx 12 backup backup 4.0K Oct  2 23:40 ..
-rw-r--r--  1 backup backup    9 Oct  2 23:03 owner

Things get created (attached) but a different error occures as well if I try to verify.

()
2023-10-04T11:03:38-04:00: verify group vmbkdata:vm/104 (1 snapshots)
2023-10-04T11:03:38-04:00: verify vmbkdata:vm/104/2023-10-03T02:03:13Z
2023-10-04T11:03:38-04:00:   check qemu-server.conf.blob
2023-10-04T11:03:38-04:00: verify vmbkdata:vm/104/2023-10-03T02:03:13Z/qemu-server.conf.blob failed: unable to load blob '"/vmbkdata/vm/104/2023-10-03T02:03:13Z/qemu-server.conf.blob"' - Permission denied (os error 13)
2023-10-04T11:03:38-04:00:   check drive-sata0.img.fidx
2023-10-04T11:03:38-04:00: verify vmbkdata:vm/104/2023-10-03T02:03:13Z/drive-sata0.img.fidx failed: Unable to open fixed index "/vmbkdata/vm/104/2023-10-03T02:03:13Z/drive-sata0.img.fidx" - Permission denied (os error 13)
2023-10-04T11:03:38-04:00: TASK ERROR: unable to update manifest blob - Atomic rename failed for file "/vmbkdata/vm/104/2023-10-03T02:03:13Z/index.json.blob" - File exists (os error 17)

Obviously the finger goes to some type of weird permissions issue but I dont get what that would be if its able to manipulate data on the datastore to some extent and not others.

 

[ggoller]

Obviously the finger goes to some type of weird permissions issue but I dont get what that would be if its able to manipulate data on the datastore to some extent and not others.

Yeah, right. It would still be worth checking the permissions though. Could you try to change the owner and group of the `.blob` and `.img.fidx` files to "backup:backup"?