[SOLVED] EACCES: Permission Denied when backing up to PBS.

[casparsmit]

Hi All,

I seem to have botched my installation of pbs and cannot seem to find the reason why.

whenever i backup a vm it results in:

INFO: starting new backup job: vzdump 100 --node stellar01 --remove 0 --mode snapshot --storage pbs
INFO: Starting Backup of VM 100 (qemu)

INFO: Backup started at 2021-10-13 12:02:08
INFO: status = running
INFO: VM Name: testvm
INFO: include disk 'scsi0' 'local:100/vm-100-disk-0.qcow2' 10G
INFO: backup mode: snapshot
INFO: ionice priority: 7
INFO: creating Proxmox Backup Server archive 'vm/100/2021-10-13T10:02:08Z'
ERROR: VM 100 qmp command 'backup' failed - backup connect failed: command error: EACCES: Permission denied
INFO: aborting backup job
INFO: resuming VM again
ERROR: Backup of VM 100 failed - VM 100 qmp command 'backup' failed - backup connect failed: command error: EACCES: Permission denied
INFO: Failed at 2021-10-13 12:02:08
INFO: Backup job finished with errors
TASK ERROR: job errors


The folders on the datastore are created with the backup:backup credentials (i already tried to chmod 777 everything in the datastore to no avail):

drwxrwxrwx 6 backup backup 4096 Oct 13 11:27 ./
drwxr-xr-x 22 root root 4096 Oct 13 11:53 ../
drwxrwxrwx 1 backup backup 1073152 Oct 13 10:35 .chunks/
drwxrwxrwx 3 backup backup 4096 Oct 13 12:14 host/
-rw-r--r-- 1 backup backup 0 Oct 13 10:35 .lock
drwxrwxrwx 3 backup backup 4096 Oct 13 12:02 vm/

Journalctl shows:


Oct 13 12:23:33 stellar01 pvedaemon[2319]: <stellar@pve> starting task UPID:stellar01:00001D20:00029295:6166B3A5:vzdump:100:stellar@pve:
Oct 13 12:23:33 stellar01 pvedaemon[7456]: INFO: starting new backup job: vzdump 100 --remove 0 --node stellar01 --mode snapshot --storage pbs
Oct 13 12:23:33 stellar01 pvedaemon[7456]: INFO: Starting Backup of VM 100 (qemu)
Oct 13 12:23:33 stellar01 proxmox-backup-proxy[3515]: GET //api2/json/backup?backup-id=100&backup-time=1634120613&backup-type=vm&benchmark=false&debug=false&store=test: 400 Bad Request: [client [::ffff:127.0.0.1]:50282] EACCES: Permission denied
Oct 13 12:23:33 stellar01 pvedaemon[7456]: VM 100 qmp command failed - VM 100 qmp command 'backup' failed - backup connect failed: command error: EACCES: Permission denied
Oct 13 12:23:33 stellar01 pvedaemon[7456]: ERROR: Backup of VM 100 failed - VM 100 qmp command 'backup' failed - backup connect failed: command error: EACCES: Permission denied
Oct 13 12:23:33 stellar01 pvedaemon[7456]: INFO: Backup job finished with errors
Oct 13 12:23:33 stellar01 pvedaemon[7456]: job errors
Oct 13 12:23:33 stellar01 pvedaemon[2319]: <stellar@pve> end task UPID:stellar01:00001D20:00029295:6166B3A5:vzdump:100:stellar@pve: job errors
Oct 13 12:23:40 stellar01 proxmox-backup-proxy[3515]: error during snapshot file listing: 'unable to load blob '"/mnt/vm/100/2021-10-13T10:02:08Z/index.json.blob"' - No such file or directory (os error 2)'
Oct 13 12:23:40 stellar01 proxmox-backup-proxy[3515]: error during snapshot file listing: 'unable to load blob '"/mnt/vm/100/2021-10-13T10:23:33Z/index.json.blob"' - No such file or directory (os error 2)'
Oct 13 12:23:40 stellar01 proxmox-backup-proxy[3515]: error during snapshot file listing: 'unable to load blob '"/mnt/host/stellar01/2021-10-13T10:14:43Z/index.json.blob"' - No such file or directory (os error 2)'
Oct 13 12:23:40 stellar01 proxmox-backup-proxy[3515]: error during snapshot file listing: 'unable to load blob '"/mnt/host/stellar01/2021-10-13T10:15:12Z/index.json.blob"' - No such file or directory (os error 2)'
Oct 13 12:24:00 stellar01 proxmox-backup-proxy[3515]: unable to start task log rotation: EACCES: Permission denied


The directory /mnt/vm/100/2021-10-13T10:02:08Z is created but remains empty.

I can list the repository from the cli:

# proxmox-backup-client list --repository root@pam@127.0.0.1:test
Password for "root@pam": **********
┌────────────────┬─────────────────────────────────────┬──────────────┬───────┐
│ group │ last snapshot │ backup-count │ files │
╞════════════════╪═════════════════════════════════════╪══════════════╪═══════╡
│ host/stellar01 │ host/stellar01/2021-10-13T10:14:43Z │ 2 │ │
├────────────────┼─────────────────────────────────────┼──────────────┼───────┤
│ vm/100 │ vm/100/2021-10-13T10:02:08Z │ 2 │ │
└────────────────┴─────────────────────────────────────┴──────────────┴───────┘

But doing a backup immediatly results in:

# proxmox-backup-client backup mydata.img:/dev/pve/root --repository root@pam@127.0.0.1:test --verbose
Password for "root@pam": **********
Starting backup: host/stellar01/2021-10-13T10:39:00Z
Client name: stellar01
Starting backup protocol: Wed Oct 13 12:39:03 2021
Error: EACCES: Permission denied

PS. I can backup to a freshly installed (other) pbs installation with the same setup with no problem
PS2. I tried removing all proxmox related stuff from the machine and reinstalled everything to no avail.

Any help would be greatly appreciated.
Kind regards,
Caspar

 

[casparsmit]

After some digging i found out that the culprit was that the /var/log/proxmox-backup/tasks directory was owned by root:root in stead of backup:backup.

Whenever you delete /var/log/proxmox-backup directory it is automatically created upon service restart. The api directory is correctly set to backup:backup but not the tasks directory.

 

[casparsmit]

Some more digging revealed that the proxmox-backup-daily-update.service creates the /var/log/proxmox-backup/tasks directory with root:root ownership if the directory doesn't exist.

maybe this has already been fixed in newer PBS versions but here's how to reproduce in pbs 1.1.13-2:

1. Stop all proxmox-backup-server services (api/proxy/server etc)
2. rm -rf /var/log/proxmox-backup/*
3. Start proxmox-backup-daily-update service
4. ls -al /var/log/proxmox-backup
5. tasks has root:root ownership.