Backup agent for Linux servers and workstations on-premises or in the public cloud
Post Reply
tommmoe
Influencer
Posts: 22
Liked: 1 time
Joined: Jul 05, 2016 11:27 pm
Full Name: Tom
Contact:

Unable to create snapshot

Post by tommmoe » Nov 30, 2016 5:15 am

Hi,

We are attempting to take a full backup a RHEL 6.4 server and it fails when creating the snapshot.

Code: Select all

2016-11-30 15:52:55 Job started at 2016-11-30 15:52:55
2016-11-30 15:52:55 Starting backup
2016-11-30 15:52:56 [error] Failed to create volume snapshot
2016-11-30 15:52:59 [error] Child execution has failed. Exit code: [1].
2016-11-30 15:52:59 [error] Failed to load module [veeamsnap] with parameters [deferiocache=0 debuglogging=0].
2016-11-30 15:52:59 [error] Failed to perform backup

Code: Select all

uname -a 
2.6.32-358.el6.x86_64

Code: Select all

rpm -qa | grep kernel-headers
kernel-headers-2.6.32-358.el6.x86_64

Code: Select all

rpm -qa | grep veeam
veeamsnap-1.0.0.678-1.noarch
veeam-1.0.0.678-1.el6.x86_64
We have uninstalled and re-installed the package but still no luck.

Anyone have any ideas?

Cheers

PTide
Veeam Software
Posts: 4247
Liked: 349 times
Joined: May 19, 2015 1:46 pm
Contact:

Re: Unable to create snapshot

Post by PTide » Nov 30, 2016 11:20 am

Hi,

Please provide kernel logs (dmesg -T) and logs from /var/log/veeam.

Thank you.

tommmoe
Influencer
Posts: 22
Liked: 1 time
Joined: Jul 05, 2016 11:27 pm
Full Name: Tom
Contact:

Re: Unable to create snapshot

Post by tommmoe » Dec 01, 2016 11:22 pm

Hi,

Unable to attach anything here so I'll post the logs in quotes.

dmesg isn't putting out any logs at the moment which is strange.. It was this morning though.

veeamsvc.log

Code: Select all

[02.12.2016 10:15:10] <140246020990720> net    |   Accepted incoming vRPC connection from '127.0.0.1:64183'.
[02.12.2016 10:15:10] <140245760726784>        | Thread started. Thread id: 140245760726784, parent id: 140246020990720, role: Client processor thread (127.0.0.1:64183)
[02.12.2016 10:15:10] <140245760726784> net    | Client connected...
[02.12.2016 10:15:10] <140245760726784> net    | Received reconnect options: [disabled].
[02.12.2016 10:15:10] <140245739747072>        | Thread started. Thread id: 140245739747072, parent id: 140245760726784, role: peer 127.0.0.1:64183
[02.12.2016 10:15:10] <140245739747072> lpbcore| Starting proxystub protocol dispatch loop.
[02.12.2016 10:15:10] <140245760726784>        | Thread finished. Role: 'Client processor thread (127.0.0.1:64183)'.
[02.12.2016 10:15:10] <140246020990720> net    |   Accepted incoming vRPC connection from '127.0.0.1:64184'.
[02.12.2016 10:15:10] <140245548328704>        | Thread started. Thread id: 140245548328704, parent id: 140246020990720, role: Client processor thread (127.0.0.1:64184)
[02.12.2016 10:15:10] <140245548328704> net    | Client connected...
[02.12.2016 10:15:10] <140245548328704> net    | Received reconnect options: [disabled].
[02.12.2016 10:15:10] <140245548328704> lpbcore| Starting new LPB session.
[02.12.2016 10:15:10] <140245548328704> lpbcore|   LpbCfgSession: Disconnecting.
[02.12.2016 10:15:10] <140245760726784>        | Thread started. Thread id: 140245760726784, parent id: 140245548328704, role: (async) LPBConfig session (127.0.0.1:64184)
[02.12.2016 10:15:10] <140245548328704>        |     Closing socket device.
[02.12.2016 10:15:10] <140245760726784> lpbcore| LpbCfgSession: Tcp loop.
[02.12.2016 10:15:10] <140245548328704> lpbcore|   LpbCfgSession: Disconnecting. ok.
[02.12.2016 10:15:10] <140245548328704>        |   Closing socket device.
[02.12.2016 10:15:10] <140245548328704> lpbcore| Starting new LPB session. ok.
[02.12.2016 10:15:10] <140245548328704>        | Thread finished. Role: 'Client processor thread (127.0.0.1:64184)'.
[02.12.2016 10:15:10] <140245739747072> lpbcore| WARN|Failed to parse system UUID: Incorrect string length. Zero UUID will be used.
[02.12.2016 10:15:13] <140245739747072> lpbcore|   Job execution service: starting worker (manager) process.
[02.12.2016 10:15:13] <140245739747072> lpbcore|     Starting manager process. Session UUID: [{d969b45d-f299-44ce-b935-3eed559394b6}]. Logs path: [/var/log/veeam/Backup/dbu02_vbkp1/Session_20161202_101513_{d969b45d-f299-44ce-b935-3eed559394b6}/Job.log]
[02.12.2016 10:15:13] <140245739747072> lpbcore|     JobMan has started. PID: [29122].
[02.12.2016 10:15:13] <140245548328704>        | Thread started. Thread id: 140245548328704, parent id: 140245739747072, role: Manager process [29122] shutdown handler.
[02.12.2016 10:15:13] <140245739747072> lpbcore|     Manager started with PID [29122]. Waiting connection.
[02.12.2016 10:15:13] <140246020990720> net    |   Accepted incoming vRPC connection from '127.0.0.1:64185'.
[02.12.2016 10:15:13] <140245729257216>        | Thread started. Thread id: 140245729257216, parent id: 140246020990720, role: Client processor thread (127.0.0.1:64185)
[02.12.2016 10:15:13] <140245729257216> net    | Client connected...
[02.12.2016 10:15:13] <140245729257216> net    | Received reconnect options: [disabled].
[02.12.2016 10:15:13] <140245750236928>        | Thread started. Thread id: 140245750236928, parent id: 140245729257216, role: peer 127.0.0.1:64185
[02.12.2016 10:15:13] <140245750236928> lpbcore| Starting proxystub protocol dispatch loop.
[02.12.2016 10:15:13] <140245729257216>        | Thread finished. Role: 'Client processor thread (127.0.0.1:64185)'.
[02.12.2016 10:15:13] <140246020990720> net    |   Accepted incoming vRPC connection from '127.0.0.1:64186'.
[02.12.2016 10:15:13] <140245537838848>        | Thread started. Thread id: 140245537838848, parent id: 140246020990720, role: Client processor thread (127.0.0.1:64186)
[02.12.2016 10:15:13] <140245537838848> net    | Client connected...
[02.12.2016 10:15:13] <140245537838848> net    | Received reconnect options: [disabled].
[02.12.2016 10:15:13] <140245537838848>        | Thread finished. Role: 'Client processor thread (127.0.0.1:64186)'.
[02.12.2016 10:15:13] <140245739747072> lpbcore|   Sending command [StartBackupJob] to manager with PID [29122]. Job ID: [29122]
[02.12.2016 10:15:13] <140245750236928>        |   Trying to connect to the endpoint [203.30.63.47:10002]
[02.12.2016 10:15:13] <140245750236928>        |   Connection status: system:0 ( Success ).
[02.12.2016 10:15:13] <140245750236928> lpbcore|   Try Authenticate to backup server
[02.12.2016 10:15:13] <140245750236928> lpbcore|     Server negotiate flags: 0xe2818235. Windows version: 6.3.9600.15
[02.12.2016 10:15:13] <140245750236928> lpbcore|   Authenticated
[02.12.2016 10:15:13] <140245750236928> lpbcore|   Connected to VBR[MIZVEEP01] version:[9.5.0.711]
[02.12.2016 10:15:14] <140245750236928> lpbcore| WARN|Failed to parse system UUID: Incorrect string length. Zero UUID will be used.
[02.12.2016 10:15:15] <140245750236928> lpbcore|   Snapshot service: creating snapshot.
[02.12.2016 10:15:16] <140245750236928> lpbcore|   Enumerating LVM volume groups...
[02.12.2016 10:15:16] <140245750236928> lpbcore|     LVM volume group: [vg_mizmxdbu02].
[02.12.2016 10:15:16] <140245750236928> lpbcore|     Enumerating logical volumes for LVM volume group: [vg_mizmxdbu02].
[02.12.2016 10:15:16] <140245750236928> lpbcore|   [1] LVM volume groups were detected.
[02.12.2016 10:15:16] <140245750236928> vsnap  |   Checking whether veeamsnap kernel module is loaded.
[02.12.2016 10:15:16] <140245750236928> vsnap  |   Module is not loaded.
[02.12.2016 10:15:16] <140245750236928> vsnap  |   Loading kernel module veeamsnap with parameters [deferiocache=0 debuglogging=0].
[02.12.2016 10:15:16] <140245750236928>        |     Argument [modprobe].
[02.12.2016 10:15:16] <140245750236928>        |     Argument [veeamsnap].
[02.12.2016 10:15:16] <140245750236928>        |     Argument [deferiocache=0].
[02.12.2016 10:15:16] <140245750236928>        |     Argument [debuglogging=0].
[02.12.2016 10:15:16] <140245750236928> vsnap  |   Loading kernel module veeamsnap with parameters [deferiocache=0 debuglogging=0]. Failed.
[02.12.2016 10:15:16] <140245750236928> vsnap  |   Opening VeeamSnap control.
[02.12.2016 10:15:16] <140245750236928> vsnap  |   Closing VeeamSnap control.
[02.12.2016 10:15:16] <140245750236928> lpbcore| ERR |Child execution has failed. Exit code: [1].
[02.12.2016 10:15:16] <140245750236928> lpbcore| >>  |--tr:Failed to execute [modprobe].
[02.12.2016 10:15:16] <140245750236928> lpbcore| >>  |Failed to load module [veeamsnap] with parameters [deferiocache=0 debuglogging=0].
[02.12.2016 10:15:16] <140245750236928> lpbcore| >>  |--tr:Unable to create snapshot.
[02.12.2016 10:15:16] <140245750236928> lpbcore| >>  |--tr:Failed to execute method [0] for class [N10lpbcorelib11interaction9proxystub21CResourcesServiceStubE].
[02.12.2016 10:15:16] <140245750236928> lpbcore| >>  |An exception was thrown from thread [140245750236928].
[02.12.2016 10:15:18] <140246020990720> net    |   Accepted incoming vRPC connection from '127.0.0.1:64190'.
[02.12.2016 10:15:18] <140245537838848>        | Thread started. Thread id: 140245537838848, parent id: 140246020990720, role: Client processor thread (127.0.0.1:64190)
[02.12.2016 10:15:18] <140245537838848> net    | Client connected...
[02.12.2016 10:15:18] <140245537838848> net    | Received reconnect options: [disabled].
[02.12.2016 10:15:18] <140245537838848> lpbcore| Starting new LPB session.
[02.12.2016 10:15:18] <140245537838848> lpbcore| Starting new LPB session. ok.
[02.12.2016 10:15:18] <140245729257216>        | Thread started. Thread id: 140245729257216, parent id: 140245537838848, role: (async) LPBConfig session (127.0.0.1:64190)
[02.12.2016 10:15:18] <140245537838848>        | Thread finished. Role: 'Client processor thread (127.0.0.1:64190)'.
[02.12.2016 10:15:18] <140245729257216> lpbcore| LpbCfgSession: Tcp loop.
[02.12.2016 10:15:18] <140245729257216> lpbcore|   LpbCfgSession: Session is finished.
[02.12.2016 10:15:18] <140245729257216> lpbcore|     Session ID: [{d969b45d-f299-44ce-b935-3eed559394b6}].
[02.12.2016 10:15:18] <140245729257216> lpbcore|     LpbCfgSession: Finding Manager [{d969b45d-f299-44ce-b935-3eed559394b6}].
[02.12.2016 10:15:18] <140245729257216> lpbcore|       Manager [{d969b45d-f299-44ce-b935-3eed559394b6}] is found and active.
[02.12.2016 10:15:18] <140245729257216> lpbcore|     LpbCfgSession: Finding Manager [{d969b45d-f299-44ce-b935-3eed559394b6}]. ok.
[02.12.2016 10:15:18] <140245729257216> lpbcore|   LpbCfgSession: Session is finished. ok.
[02.12.2016 10:15:18] <140245729257216> lpbcore|   LpbCfgSession: Disconnecting.
[02.12.2016 10:15:18] <140245729257216>        |     Closing socket device.
[02.12.2016 10:15:18] <140245729257216> lpbcore|   LpbCfgSession: Disconnecting. ok.
[02.12.2016 10:15:18] <140245729257216> lpbcore| LpbCfgSession: Tcp loop. ok.
[02.12.2016 10:15:18] <140245729257216>        | Thread finished. Role: '(async) LPBConfig session (127.0.0.1:64190)'.
[02.12.2016 10:15:18] <140245750236928>        |   Closing socket device.
[02.12.2016 10:15:18] <140245750236928> lpbcore| Starting proxystub protocol dispatch loop. ok.
[02.12.2016 10:15:18] <140245750236928>        | Closing socket device.
[02.12.2016 10:15:18] <140245750236928>        | Thread finished. Role: 'peer 127.0.0.1:64185'.
[02.12.2016 10:15:18] <140245548328704> lpbcore| Manager process [29122] has been shutdown.
[02.12.2016 10:15:18] <140245548328704>        | Thread finished. Role: 'Manager process [29122] shutdown handler.'.
[02.12.2016 10:15:23] <140245739747072> lpbcore| Starting proxystub protocol dispatch loop. ok.
[02.12.2016 10:15:23] <140245739747072>        | Closing socket device.
[02.12.2016 10:15:23] <140245739747072>        | Thread finished. Role: 'peer 127.0.0.1:64183'.
[02.12.2016 10:15:23] <140245760726784> lpbcore| LpbCfgSession: Tcp loop. Failed.
[02.12.2016 10:15:23] <140245760726784> lpbcore| ERR |LpbCfgSession failed.
[02.12.2016 10:15:23] <140245760726784> lpbcore| >>  |read: End of file
[02.12.2016 10:15:23] <140245760726784> lpbcore| >>  |--tr:Cannot read data from the socket. Requested data size: [4].
[02.12.2016 10:15:23] <140245760726784> lpbcore| >>  |An exception was thrown from thread [140245760726784].
[02.12.2016 10:15:23] <140245760726784>        | Thread finished. Role: '(async) LPBConfig session (127.0.0.1:64184)'.
[02.12.2016 10:16:18] <140246000011008> lpbcore|   Job manager process with PID [29122] is terminating.
[02.12.2016 10:16:18] <140246010500864> lpbcore|   Terminating job manager process with PID [29122].
[02.12.2016 10:16:18] <140246010500864>        |   Closing socket device.

PTide
Veeam Software
Posts: 4247
Liked: 349 times
Joined: May 19, 2015 1:46 pm
Contact:

Re: Unable to create snapshot

Post by PTide » Dec 02, 2016 9:38 am

You should run the backup job again and collect dmesg logs right after the job fails. You can share the logs by sending me a link to dropbox via private message.

Thanks

tommmoe
Influencer
Posts: 22
Liked: 1 time
Joined: Jul 05, 2016 11:27 pm
Full Name: Tom
Contact:

Re: Unable to create snapshot

Post by tommmoe » Dec 14, 2016 4:56 am

Hi PTide,

Unfortunately the upgrade didn't fix our problem.

Here are the logs

https://ufile.io/f3cfa

Cheers

PTide
Veeam Software
Posts: 4247
Liked: 349 times
Joined: May 19, 2015 1:46 pm
Contact:

Re: Unable to create snapshot

Post by PTide » Dec 14, 2016 11:13 am

Could you please check kernel-devel version as well?

Thanks

tommmoe
Influencer
Posts: 22
Liked: 1 time
Joined: Jul 05, 2016 11:27 pm
Full Name: Tom
Contact:

Re: Unable to create snapshot

Post by tommmoe » Dec 14, 2016 10:07 pm 1 person likes this post

No problem,

kernel-devel-2.6.32-642.6.1.el6.x86_64

I'm guessing that the version needs to match our kernel, I guess this is what happens when I can't use yum and attempt to do things manually.

I'll downgrade the devel package to the right version and let you know what happens!

Cheers

Post Reply

Who is online

Users browsing this forum: No registered users and 3 guests