Unable to create snapshot

Backup agent for Linux servers and workstations on-premises or in the public cloud

Unable to create snapshot

Veeam Logoby tommmoe » Wed 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
tommmoe
Influencer
 
Posts: 20
Liked: 1 time
Joined: Tue Jul 05, 2016 11:27 pm
Full Name: Tom

Re: Unable to create snapshot

Veeam Logoby PTide » Wed Nov 30, 2016 11:20 am

Hi,

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

Thank you.
PTide
Veeam Software
 
Posts: 3140
Liked: 262 times
Joined: Tue May 19, 2015 1:46 pm

Re: Unable to create snapshot

Veeam Logoby tommmoe » Thu 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.
tommmoe
Influencer
 
Posts: 20
Liked: 1 time
Joined: Tue Jul 05, 2016 11:27 pm
Full Name: Tom

Re: Unable to create snapshot

Veeam Logoby PTide » Fri 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
PTide
Veeam Software
 
Posts: 3140
Liked: 262 times
Joined: Tue May 19, 2015 1:46 pm

Re: Unable to create snapshot

Veeam Logoby tommmoe » Wed 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
tommmoe
Influencer
 
Posts: 20
Liked: 1 time
Joined: Tue Jul 05, 2016 11:27 pm
Full Name: Tom

Re: Unable to create snapshot

Veeam Logoby PTide » Wed Dec 14, 2016 11:13 am

Could you please check kernel-devel version as well?

Thanks
PTide
Veeam Software
 
Posts: 3140
Liked: 262 times
Joined: Tue May 19, 2015 1:46 pm

Re: Unable to create snapshot

Veeam Logoby tommmoe » Wed 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
tommmoe
Influencer
 
Posts: 20
Liked: 1 time
Joined: Tue Jul 05, 2016 11:27 pm
Full Name: Tom


Return to Veeam Agent for Linux



Who is online

Users browsing this forum: No registered users and 4 guests