Standalone backup agents for Linux, Mac, AIX & Solaris workloads on-premises or in the public cloud
Post Reply
goose_ws
Influencer
Posts: 11
Liked: 4 times
Joined: Aug 13, 2020 2:02 am
Full Name: goose
Contact:
Contact goose_ws

Unable to initiate backup

Post by goose_ws »

Veeam case ID is 04439354

I've got a new host that I've successfully installed Veeam on. Host is running Debian Stable.

I'm trying to run a backup job, configured to backup to a directory in /mnt/ which is actually an sshfs mounted directory. I have an identical setup on another Debian host. The root user (which veeam runs as) is able to read/write to that directory without issue.

The backup fails to run, I'm unsure why based on the error message.

Log:

Code: Select all

[13.10.2020 11:48:52.372] <139809580641280> cli    | Initializing new log filter.
[13.10.2020 11:48:52.372] <139809580641280> lpbman | Current group name [veeam]
[13.10.2020 11:48:52.372] <139809580641280>        | ====================================================================================
[13.10.2020 11:48:52.372] <139809580641280> lpb    | {
[13.10.2020 11:48:52.372] <139809580641280> lpb    |   Veeam Agent for Linux: veeamjobman.
[13.10.2020 11:48:52.372] <139809580641280> lpb    |   Version: 4.0.1.2365
[13.10.2020 11:48:52.372] <139809580641280> lpb    |   Build date: 13/07/2020
[13.10.2020 11:48:52.372] <139809580641280> lpb    |   Build edition: standard
[13.10.2020 11:48:52.372] <139809580641280> lpb    |   PID: 28234
[13.10.2020 11:48:52.372] <139809580641280> vmb    |   hostname: rocinante
[13.10.2020 11:48:52.372] <139809580641280> vmb    |   uname
[13.10.2020 11:48:52.372] <139809580641280> vmb    |     sysname : Linux
[13.10.2020 11:48:52.372] <139809580641280> vmb    |     release : 4.19.0-11-amd64
[13.10.2020 11:48:52.372] <139809580641280> vmb    |     version : #1 SMP Debian 4.19.146-1 (2020-09-17)
[13.10.2020 11:48:52.372] <139809580641280> vmb    |     machine : x86_64
[13.10.2020 11:48:52.372] <139809580641280> lpb    | }
[13.10.2020 11:48:52.373] <139809580641280> lpbcore| Connecting to veeamservice...
[13.10.2020 11:48:52.373] <139809580641280> lpbcore| Connecting to veeamservice... ok.
[13.10.2020 11:48:52.373] <139809580641280> lpbman | Main thread has started.
[13.10.2020 11:48:52.374] <139809580641280> lpbcore| No license installed.
[13.10.2020 11:48:52.376] <139809580641280> lpbcore| LpbManSession: Processing commands.
[13.10.2020 11:48:52.378] <139809580641280> lpbcore|   Sending PID: [28234].
[13.10.2020 11:48:52.378] <139809580641280> lpbcore|   Sending Session UUID: [{3ca72e68-1e6d-4cb8-a2fe-9141d5060b88}].
[13.10.2020 11:48:52.378] <139809580641280> lpbcore|   Waiting for a command.
[13.10.2020 11:48:52.513] <139809580641280> lpbcore|   LpbManSession: Starting backup job.
[13.10.2020 11:48:52.513] <139809580641280> lpbcore|     Job UUID: [{a7fa23ad-194b-414c-966a-639859bdccbb}] (normal priority).
[13.10.2020 11:48:52.513] <139809580641280> lpbcore|     Is active full? [false].
[13.10.2020 11:48:52.513] <139809580641280> lpbcore|     Is snapshot required? [true].
[13.10.2020 11:48:52.528] <139809580641280> lpbcore|     System information:
[13.10.2020 11:48:52.528] <139809580641280> lpbcore|       Running [lsb_release -a].
[13.10.2020 11:48:52.579] <139809580641280> lpbcore|         Distributor ID:    Debian
[13.10.2020 11:48:52.579] <139809580641280> lpbcore|         Description:       Debian GNU/Linux 10 (buster)
[13.10.2020 11:48:52.579] <139809580641280> lpbcore|         Release:   10
[13.10.2020 11:48:52.579] <139809580641280> lpbcore|         Codename:  buster
[13.10.2020 11:48:52.579] <139809580641280> lpbcore|       Running [cat /etc/*release].
[13.10.2020 11:48:52.581] <139809580641280> lpbcore|         PRETTY_NAME="Debian GNU/Linux 10 (buster)"
[13.10.2020 11:48:52.581] <139809580641280> lpbcore|         NAME="Debian GNU/Linux"
[13.10.2020 11:48:52.581] <139809580641280> lpbcore|         VERSION_ID="10"
[13.10.2020 11:48:52.581] <139809580641280> lpbcore|         VERSION="10 (buster)"
[13.10.2020 11:48:52.581] <139809580641280> lpbcore|         VERSION_CODENAME=buster
[13.10.2020 11:48:52.581] <139809580641280> lpbcore|         ID=debian
[13.10.2020 11:48:52.581] <139809580641280> lpbcore|         HOME_URL="https://www.debian.org/"
[13.10.2020 11:48:52.581] <139809580641280> lpbcore|         SUPPORT_URL="https://www.debian.org/support"
[13.10.2020 11:48:52.581] <139809580641280> lpbcore|         BUG_REPORT_URL="https://bugs.debian.org/"
[13.10.2020 11:48:52.581] <139809580641280> lpbcore|       Running [lsblk].
[13.10.2020 11:48:52.588] <139809580641280> lpbcore|         NAME                     MAJ:MIN RM  SIZE RO TYPE MOUNTPOINT
[13.10.2020 11:48:52.588] <139809580641280> lpbcore|         sr0                       11:0    1  349M  0 rom
[13.10.2020 11:48:52.588] <139809580641280> lpbcore|         vda                      254:0    0   32G  0 disk
[13.10.2020 11:48:52.588] <139809580641280> lpbcore|         ├─vda1                   254:1    0  243M  0 part /boot
[13.10.2020 11:48:52.588] <139809580641280> lpbcore|         ├─vda2                   254:2    0    1K  0 part
[13.10.2020 11:48:52.588] <139809580641280> lpbcore|         └─vda5                   254:5    0 31.8G  0 part
[13.10.2020 11:48:52.588] <139809580641280> lpbcore|           ├─rocinante--vg-root   253:0    0 10.6G  0 lvm  /
[13.10.2020 11:48:52.588] <139809580641280> lpbcore|           ├─rocinante--vg-swap_1 253:1    0    2G  0 lvm
[13.10.2020 11:48:52.588] <139809580641280> lpbcore|           └─rocinante--vg-home   253:2    0 19.2G  0 lvm  /home
[13.10.2020 11:48:52.588] <139809580641280> lpbcore|         vdb                      254:16   0    4T  0 disk
[13.10.2020 11:48:52.588] <139809580641280> lpbcore|         └─vdb1                   254:17   0    4T  0 part /mnt/torpedo
[13.10.2020 11:48:52.588] <139809580549888>        | Thread started. Thread id: 139809580549888, parent id: 139809580641280, role: Volume backup job execution
[13.10.2020 11:48:52.592] <139809580549888> lpbcore| BackupJobPerformer: Creating backup.
[13.10.2020 11:48:52.763] <139809580641280> lpbcore|   LpbManSession: Starting backup job. ok.
[13.10.2020 11:48:52.765] <139809580549888> lpbcore| BackupJobPerformer: Creating backup. Failed.
[13.10.2020 11:48:52.765] <139809580549888> vmb    | [SessionLog][error] Failed to perform backup.
[13.10.2020 11:48:52.796] <139809580549888> vmb    | [SessionLog][error] Permission denied.
[13.10.2020 11:48:52.826] <139809580549888> vmb    | [SessionLog][error] Failed to check repository Repository_1 {36665a3d-d7bd-46c4-89ef-57b8ba184926}.
[13.10.2020 11:48:52.861] <139809580549888> vmb    | [SessionLog][error] Processing finished with errors at 2020-10-13 11:48:52 GMT.
[13.10.2020 11:48:52.890] <139809580549888> lpbcore| ERR |Permission denied
[13.10.2020 11:48:52.890] <139809580549888> lpbcore| >>  |--tr:CPathUtils: Failed to check whether [/mnt/vergil/] exists.
[13.10.2020 11:48:52.890] <139809580549888> lpbcore| >>  |Failed to check repository Repository_1 {36665a3d-d7bd-46c4-89ef-57b8ba184926}.
[13.10.2020 11:48:52.890] <139809580549888> lpbcore| >>  |--tr:Failed to prepare destination/repository.
[13.10.2020 11:48:52.890] <139809580549888> lpbcore| >>  |Backup job has failed.
[13.10.2020 11:48:52.890] <139809580549888> lpbcore| >>  |An exception was thrown from thread [139809580549888].
[13.10.2020 11:48:52.947] <139809580641280>        |   Closing socket device.
[13.10.2020 11:48:52.947] <139809580641280> lpbcore| LpbManSession: Processing commands. ok.
[13.10.2020 11:48:52.947] <139809580641280>        | Closing socket device.
[13.10.2020 11:48:52.947] <139809580549888> lpbcore| JOB STATUS: FAILED.
[13.10.2020 11:48:52.947] <139809580549888>        | Thread finished. Role: 'Volume backup job execution'.
[13.10.2020 11:48:52.948] <139809580641280>        | Closing socket device.
[13.10.2020 11:48:52.948] <139809580641280>        | Closing socket device.
[13.10.2020 11:48:52.948] <139809580641280> lpbman | Application session has been finished.
Top
Natalia Lupacheva
Veteran
Posts: 1143
Liked: 302 times
Joined: Apr 27, 2020 12:46 pm
Full Name: Natalia Lupacheva
Contact:
Contact Natalia Lupacheva

Re: Unable to initiate backup

Post by Natalia Lupacheva »

Hi,

Code: Select all

Failed to check whether [/mnt/vergil/] exists
seems like a permission issue.
Did you check the permissions for the user who ran the backup job?

Thanks!
Top
goose_ws
Influencer
Posts: 11
Liked: 4 times
Joined: Aug 13, 2020 2:02 am
Full Name: goose
Contact:
Contact goose_ws

Re: Unable to initiate backup

Post by goose_ws »

The user running the backup is the root user, who does have read/write permissions in that directory.

The directory is mounted via sshfs

Code: Select all

root@rocinante:~# mount | grep vergil
rocinante@[redacted]:/mnt/userdata/veeam/rocinante on /mnt/vergil type fuse.sshfs (rw,nosuid,nodev,relatime,user_id=0,group_id=0)
root@rocinante:~# ps aux | grep sshfs
root     28589  0.0  0.0 160472   284 ?        Ssl  13:02   0:00 /usr/bin/sshfs -o reconnect,ServerAliveInterval=15,ServerAliveCountMax=3 rocinante@[redacted]:/mnt/userdata/veeam/rocinante /mnt/vergil
root     28622  0.0  0.0   6076   872 pts/1    S+   13:03   0:00 grep sshfs
root@rocinante:/mnt/vergil#
It can be changed to, read, and written to, by root

Code: Select all

root@rocinante:~# cd /mnt/vergil/
root@rocinante:/mnt/vergil# ls -lah
total 8.0K
drwxr-x--- 1 1007 1007    2 Oct 13 12:01 .
drwxr-xr-x 4 root root 4.0K Oct 13 11:30 ..
root@rocinante:/mnt/vergil# echo "test" > $(date +%s.txt)
root@rocinante:/mnt/vergil# ls
1602608612.txt
root@rocinante:/mnt/vergil# cat 1602608612.txt
test
root@rocinante:/mnt/vergil# stat 1602608612.txt
  File: 1602608612.txt
  Size: 5               Blocks: 8          IO Block: 4096   regular file
Device: 2ch/44d Inode: 2           Links: 1
Access: (0644/-rw-r--r--)  Uid: ( 1007/ UNKNOWN)   Gid: ( 1007/ UNKNOWN)
Access: 2020-10-13 13:03:33.000000000 -0400
Modify: 2020-10-13 13:03:33.000000000 -0400
Change: 2020-10-13 13:03:33.000000000 -0400
 Birth: -
root@rocinante:/mnt/vergil# rm 1602608612.txt
root@rocinante:/mnt/vergil# mkdir testdir
root@rocinante:/mnt/vergil# stat testdir/
  File: testdir/
  Size: 2               Blocks: 8          IO Block: 4096   directory
Device: 2ch/44d Inode: 3           Links: 1
Access: (0755/drwxr-xr-x)  Uid: ( 1007/ UNKNOWN)   Gid: ( 1007/ UNKNOWN)
Access: 2020-10-13 13:03:53.000000000 -0400
Modify: 2020-10-13 13:03:53.000000000 -0400
Change: 2020-10-13 13:03:53.000000000 -0400
 Birth: -
root@rocinante:/mnt/vergil# rmdir testdir
root@rocinante:/mnt/vergil#
But Veeam fails to back up to it

Code: Select all

root@rocinante:/mnt/vergil# veeamconfig job start --id {a7fa23ad-194b-414c-966a-639859bdccbb}
Backup job has been started.
Session ID: [{54b5ab6b-26de-480e-8d02-e5a3739e3663}].
Logs stored in: [/var/log/veeam/Backup/rocinante/Session_20201013_130425_{54b5ab6b-26de-480e-8d02-e5a3739e3663}].
root@rocinante:/mnt/vergil# cat /var/log/veeam/Backup/rocinante/Session_20201013_130425_\{54b5ab6b-26de-480e-8d02-e5a3739e3663\}/Job.log
[13.10.2020 13:04:25.934] <140218749688832> cli    | Initializing new log filter.
[13.10.2020 13:04:25.934] <140218749688832> lpbman | Current group name [veeam]
[13.10.2020 13:04:25.934] <140218749688832>        | ====================================================================================
[13.10.2020 13:04:25.934] <140218749688832> lpb    | {
[13.10.2020 13:04:25.934] <140218749688832> lpb    |   Veeam Agent for Linux: veeamjobman.
[13.10.2020 13:04:25.934] <140218749688832> lpb    |   Version: 4.0.1.2365
[13.10.2020 13:04:25.934] <140218749688832> lpb    |   Build date: 13/07/2020
[13.10.2020 13:04:25.934] <140218749688832> lpb    |   Build edition: standard
[13.10.2020 13:04:25.934] <140218749688832> lpb    |   PID: 28641
[13.10.2020 13:04:25.934] <140218749688832> vmb    |   hostname: rocinante
[13.10.2020 13:04:25.934] <140218749688832> vmb    |   uname
[13.10.2020 13:04:25.934] <140218749688832> vmb    |     sysname : Linux
[13.10.2020 13:04:25.934] <140218749688832> vmb    |     release : 4.19.0-11-amd64
[13.10.2020 13:04:25.934] <140218749688832> vmb    |     version : #1 SMP Debian 4.19.146-1 (2020-09-17)
[13.10.2020 13:04:25.934] <140218749688832> vmb    |     machine : x86_64
[13.10.2020 13:04:25.934] <140218749688832> lpb    | }
[13.10.2020 13:04:25.935] <140218749688832> lpbcore| Connecting to veeamservice...
[13.10.2020 13:04:25.935] <140218749688832> lpbcore| Connecting to veeamservice... ok.
[13.10.2020 13:04:25.935] <140218749688832> lpbman | Main thread has started.
[13.10.2020 13:04:25.936] <140218749688832> lpbcore| No license installed.
[13.10.2020 13:04:25.939] <140218749688832> lpbcore| LpbManSession: Processing commands.
[13.10.2020 13:04:25.940] <140218749688832> lpbcore|   Sending PID: [28641].
[13.10.2020 13:04:25.940] <140218749688832> lpbcore|   Sending Session UUID: [{54b5ab6b-26de-480e-8d02-e5a3739e3663}].
[13.10.2020 13:04:25.940] <140218749688832> lpbcore|   Waiting for a command.
[13.10.2020 13:04:26.014] <140218749688832> lpbcore|   LpbManSession: Starting backup job.
[13.10.2020 13:04:26.014] <140218749688832> lpbcore|     Job UUID: [{a7fa23ad-194b-414c-966a-639859bdccbb}] (normal priority).
[13.10.2020 13:04:26.014] <140218749688832> lpbcore|     Is active full? [false].
[13.10.2020 13:04:26.014] <140218749688832> lpbcore|     Is snapshot required? [true].
[13.10.2020 13:04:26.064] <140218749688832> lpbcore|     System information:
[13.10.2020 13:04:26.064] <140218749688832> lpbcore|       Running [lsb_release -a].
[13.10.2020 13:04:26.114] <140218749688832> lpbcore|         Distributor ID:    Debian
[13.10.2020 13:04:26.114] <140218749688832> lpbcore|         Description:       Debian GNU/Linux 10 (buster)
[13.10.2020 13:04:26.114] <140218749688832> lpbcore|         Release:   10
[13.10.2020 13:04:26.114] <140218749688832> lpbcore|         Codename:  buster
[13.10.2020 13:04:26.114] <140218749688832> lpbcore|       Running [cat /etc/*release].
[13.10.2020 13:04:26.116] <140218749688832> lpbcore|         PRETTY_NAME="Debian GNU/Linux 10 (buster)"
[13.10.2020 13:04:26.116] <140218749688832> lpbcore|         NAME="Debian GNU/Linux"
[13.10.2020 13:04:26.116] <140218749688832> lpbcore|         VERSION_ID="10"
[13.10.2020 13:04:26.116] <140218749688832> lpbcore|         VERSION="10 (buster)"
[13.10.2020 13:04:26.116] <140218749688832> lpbcore|         VERSION_CODENAME=buster
[13.10.2020 13:04:26.116] <140218749688832> lpbcore|         ID=debian
[13.10.2020 13:04:26.116] <140218749688832> lpbcore|         HOME_URL="https://www.debian.org/"
[13.10.2020 13:04:26.116] <140218749688832> lpbcore|         SUPPORT_URL="https://www.debian.org/support"
[13.10.2020 13:04:26.116] <140218749688832> lpbcore|         BUG_REPORT_URL="https://bugs.debian.org/"
[13.10.2020 13:04:26.116] <140218749688832> lpbcore|       Running [lsblk].
[13.10.2020 13:04:26.123] <140218749688832> lpbcore|         NAME                     MAJ:MIN RM  SIZE RO TYPE MOUNTPOINT
[13.10.2020 13:04:26.123] <140218749688832> lpbcore|         sr0                       11:0    1  349M  0 rom
[13.10.2020 13:04:26.123] <140218749688832> lpbcore|         vda                      254:0    0   32G  0 disk
[13.10.2020 13:04:26.123] <140218749688832> lpbcore|         ├─vda1                   254:1    0  243M  0 part /boot
[13.10.2020 13:04:26.123] <140218749688832> lpbcore|         ├─vda2                   254:2    0    1K  0 part
[13.10.2020 13:04:26.123] <140218749688832> lpbcore|         └─vda5                   254:5    0 31.8G  0 part
[13.10.2020 13:04:26.123] <140218749688832> lpbcore|           ├─rocinante--vg-root   253:0    0 10.6G  0 lvm  /
[13.10.2020 13:04:26.123] <140218749688832> lpbcore|           ├─rocinante--vg-swap_1 253:1    0    2G  0 lvm
[13.10.2020 13:04:26.123] <140218749688832> lpbcore|           └─rocinante--vg-home   253:2    0 19.2G  0 lvm  /home
[13.10.2020 13:04:26.123] <140218749688832> lpbcore|         vdb                      254:16   0    4T  0 disk
[13.10.2020 13:04:26.123] <140218749688832> lpbcore|         └─vdb1                   254:17   0    4T  0 part /mnt/torpedo
[13.10.2020 13:04:26.123] <140218749597440>        | Thread started. Thread id: 140218749597440, parent id: 140218749688832, role: Volume backup job execution
[13.10.2020 13:04:26.126] <140218749597440> lpbcore| BackupJobPerformer: Creating backup.
[13.10.2020 13:04:26.156] <140218749688832> lpbcore|   LpbManSession: Starting backup job. ok.
[13.10.2020 13:04:26.156] <140218749597440> lpbcore| BackupJobPerformer: Creating backup. Failed.
[13.10.2020 13:04:26.156] <140218749597440> vmb    | [SessionLog][error] Failed to perform backup.
[13.10.2020 13:04:26.186] <140218749597440> vmb    | [SessionLog][error] Permission denied.
[13.10.2020 13:04:26.211] <140218749597440> vmb    | [SessionLog][error] Failed to check repository Repository_1 {36665a3d-d7bd-46c4-89ef-57b8ba184926}.
[13.10.2020 13:04:26.264] <140218749597440> vmb    | [SessionLog][error] Processing finished with errors at 2020-10-13 13:04:26 GMT.
[13.10.2020 13:04:26.300] <140218749597440> lpbcore| ERR |Permission denied
[13.10.2020 13:04:26.300] <140218749597440> lpbcore| >>  |--tr:CPathUtils: Failed to check whether [/mnt/vergil/] exists.
[13.10.2020 13:04:26.300] <140218749597440> lpbcore| >>  |Failed to check repository Repository_1 {36665a3d-d7bd-46c4-89ef-57b8ba184926}.
[13.10.2020 13:04:26.300] <140218749597440> lpbcore| >>  |--tr:Failed to prepare destination/repository.
[13.10.2020 13:04:26.300] <140218749597440> lpbcore| >>  |Backup job has failed.
[13.10.2020 13:04:26.300] <140218749597440> lpbcore| >>  |An exception was thrown from thread [140218749597440].
[13.10.2020 13:04:26.372] <140218749688832>        |   Closing socket device.
[13.10.2020 13:04:26.372] <140218749688832> lpbcore| LpbManSession: Processing commands. ok.
[13.10.2020 13:04:26.372] <140218749688832>        | Closing socket device.
[13.10.2020 13:04:26.372] <140218749597440> lpbcore| JOB STATUS: FAILED.
[13.10.2020 13:04:26.372] <140218749597440>        | Thread finished. Role: 'Volume backup job execution'.
[13.10.2020 13:04:26.372] <140218749688832>        | Closing socket device.
[13.10.2020 13:04:26.372] <140218749688832>        | Closing socket device.
[13.10.2020 13:04:26.373] <140218749688832> lpbman | Application session has been finished.
root@rocinante:/mnt/vergil#
Is there some way to increase the verbosity of the logging, so I can get more information on the failure?
Top
goose_ws
Influencer
Posts: 11
Liked: 4 times
Joined: Aug 13, 2020 2:02 am
Full Name: goose
Contact:
Contact goose_ws

Re: Unable to initiate backup

Post by goose_ws » 4 people like this post

For anyone else who comes across this in the future, I solved it by adding the 'allow_other' option to my sshfs mount options, which was not enabled by default in my /etc/fuse.conf
Top
Post Reply

Return to “Veeam Agents for Linux, Mac, AIX & Solaris”



Who is online

Users browsing this forum: No registered users and 17 guests