Unable to create snapshot

[tommmoe]

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]

Hi,

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

Thank you.

[tommmoe]

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]

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]

Hi PTide,

Unfortunately the upgrade didn't fix our problem.

Here are the logs

https://ufile.io/f3cfa

Cheers

[PTide]

Could you please check kernel-devel version as well?

Thanks

[tommmoe]

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