Re: VDP backups always fail regardless of state

AndreasY2011101 · ‎04-08-2014

Hello,

I have tried to deploy VDP of several versions with the same result in order to evaluate the product but can't get it to backup a single host regardless of powered on or shut down. The deployment were done following the VDP administration guide to the point.

During the process I started out with VDP 5.1 then upgraded both vcenter server and VDP to 5.5 and 5.5.6 respectively with almost the same issue. I have set new vdp users with administrative permissions, redeployed vdp, tested several different vm hosts in all possible states with or without snapshots present but same result. Backup starts but fail in under a minute due to what looks like no permission to read the .vmx file, I can however download and view the file using infrastructure client as long as the vm host is shut down.

I have also tried all suggested solutions that I could find on the kb, no special chars in the datacenter etc.

I am starting to get a bit frustrated and the feeling is that this product is flawed. Any ideas would be greatly appreciated.

The most recent attempts in VDP 5.5.6 give the following log output:

====================================================================================================================================================

Client Name ::CentOS QNAP Management Server | Workorder ID :: null | Completed Time ::Tue, 8 Apr 2014 23:42:57 CEST

=====================================================================================================================================================

*********** /usr/local/avamarclient/var-proxy-7/InitialTestBackup-1396993349036-514330c10e51fd762447275e43f5f51df0a8780b-1016-vmimagel.log ***********

--------------------------------------------------------------------------------------------------------

----- START avvcbimage log 2014-04-08 23:42:31 CEST [7.0.182-99 Linux-x86_64]

--------------------------------------------------------------------------------------------------------

2014-04-08T23:42:31.936+2:00 avvcbimage Info <5008>: Logging to /usr/local/avamarclient/var-proxy-7/InitialTestBackup-1396993349036-514330c10e51fd762447275e43f5f51df0a8780b-1016-vmimagel.log

2014-04-08T23:42:31.936+2:00 avvcbimage Info <5174>: - Reading /root/.avamar

2014-04-08T23:42:31.936+2:00 avvcbimage Info <5174>: - Reading /usr/local/avamar/etc/usersettings.cfg

2014-04-08T23:42:31.936+2:00 avvcbimage Info <5174>: - Reading /usr/local/avamarclient/var-proxy-7/avvcbimage.cmd

2014-04-08T23:42:31.936+2:00 avvcbimage Info <5174>: - Reading /usr/local/avamarclient/var/avvcbimageAll.cmd

2014-04-08T23:42:31.938+2:00 avvcbimage Info <6673>: CTL listening on port 51445

2014-04-08T23:42:31.939+2:00 avvcbimage Info <10684>: Setting ctl message version to 3 (from 1)

2014-04-08T23:42:31.939+2:00 avvcbimage Info <16136>: Setting ctl max message size to 268435456

2014-04-08T23:42:31.942+2:00 avvcbimage Warning <6788>: Found unknown section 'browse-from-catalog' in workorder, ignoring

2014-04-08T23:42:31.943+2:00 avvcbimage Warning <17809>: VAMI Statistics Push Provider DISABLED.

2014-04-08T23:42:31.961+2:00 avvcbimage Info <18664>: Login(https://vcenter.lab.local:443/sdk) Datacenter: 'Datacenter01'

2014-04-08T23:42:31.961+2:00 avvcbimage Info <0000>: - connected to 'VirtualCenter' - version: 'VMware vCenter Server 5.5.0 build-1623101', apiVersion:'5.5'

2014-04-08T23:42:32.024+2:00 avvcbimage Info <14692>: Login test is OK.

2014-04-08T23:42:32.079+2:00 avvcbimage Info <0000>: VM Info: VMX version 4(F), ctk enabled(T), fault tolerant (F), Guest OS CentOS 4/5/6 (64-bit), Cloud UUID = NoUUID. version=8

2014-04-08T23:42:32.129+2:00 avvcbimage Info <14625>: WorkOrder Disk Info:

Disk '2000': file(base):'[QNAP02-Datastore201] CentOS QNAP Management Server/CentOS QNAP Management Server.vmdk', backItUp=1

snapshot file:'[QNAP02-Datastore201] CentOS QNAP Management Server/CentOS QNAP Management Server.vmdk'

prior size(KB):0, current size(KB):16777216, match=0

prior change block ID:''

Datastore:'QNAP02-Datastore201' Directly Accessible=1

2014-04-08T23:42:32.130+2:00 avvcbimage Info <11979>: proxy VM DNS name is: 127.0.0.2,vdp-hq-esx01.lab.local,vdp-hq-esx01,192.168.0.12

2014-04-08T23:42:32.130+2:00 avvcbimage Info <18672>: proxy VM Instance name is: vdp-hq-esx01.lab.local-proxy-7

2014-04-08T23:42:32.130+2:00 avvcbimage Info <17793>: proxy VM Moref is: vm-1401

2014-04-08T23:42:32.130+2:00 avvcbimage Info <16010>: vCenter 'Datacenter01' is vcenter.lab.local

2014-04-08T23:42:32.130+2:00 avvcbimage Info <11981>: VM's host is hq-esx02.lab.local

2014-04-08T23:42:32.130+2:00 avvcbimage Info <11982>: VM's primary storage location is [QNAP02-Datastore201] CentOS QNAP Management Server/CentOS QNAP Management Server.vmx

2014-04-08T23:42:32.130+2:00 avvcbimage Info <11983>: VM's vCenter ID is vm-1277

2014-04-08T23:42:33.320+2:00 avvcbimage Info <0000>: Proxy Host Name=hq-esx01.lab.local(5.1 build-1157734) VM Host Name=hq-esx02.lab.local(5.1 build-1157734)

2014-04-08T23:42:33.320+2:00 avvcbimage Info <11984>: VM's backup account on vdp-hq-esx01.lab.local is /vcenter.lab.local/VirtualMachines/CentOS_QNAP_Management_Server_Ui0niBEuhZa7fTHZF4vjOg

2014-04-08T23:42:33.320+2:00 avvcbimage Info <11986>: Changed block tracking is engaged for this VM

2014-04-08T23:42:33.320+2:00 avvcbimage Info <11988>: A reference to a valid prior backup is not available so this will be a full level zero backup.

2014-04-08T23:42:33.404+2:00 avvcbimage Info <17779>: task task-5528 migration status:0

2014-04-08T23:42:33.446+2:00 avvcbimage Warning <6788>: Found unknown section 'browse-from-catalog' in workorder, ignoring

2014-04-08T23:42:33.448+2:00 avvcbimage Info <5174>: - Reading /usr/local/avamarclient/var-proxy-7/avvcbimage.cmd

2014-04-08T23:42:33.448+2:00 avvcbimage Info <5174>: - Reading /usr/local/avamarclient/var/avvcbimageAll.cmd

2014-04-08T23:42:33.448+2:00 avvcbimage Info <7084>: target[0]=[QNAP02-Datastore201] CentOS QNAP Management Server/CentOS QNAP Management Server.vmdk

2014-04-08T23:42:33.461+2:00 avvcbimage Info <18664>: Login(https://vcenter.lab.local:443/sdk) Datacenter: 'Datacenter01'

2014-04-08T23:42:33.462+2:00 avvcbimage Info <0000>: - connected to 'VirtualCenter' - version: 'VMware vCenter Server 5.5.0 build-1623101', apiVersion:'5.5'

2014-04-08T23:42:33.486+2:00 avvcbimage Info <14692>: Login test is OK.

2014-04-08T23:42:33.508+2:00 avvcbimage Info <16041>: VDDK:OBJLIB-LIB: Objlib initialized.

2014-04-08T23:42:33.508+2:00 avvcbimage Info <16041>: VDDK:VixDiskLib: Attempting to locate advanced transport module in "/usr/lib/vmware-vix-disklib".

2014-04-08T23:42:34.430+2:00 avvcbimage Info <16041>: VDDK:VixDiskLib: Advanced transport plugin was successfully loaded into vixDiskLib.

2014-04-08T23:42:34.430+2:00 avvcbimage Info <16041>: VDDK:VixDiskLib: Enabling advanced transport modes.

2014-04-08T23:42:34.430+2:00 avvcbimage Info <16041>: VDDK:OBJLIB-LIB: Objlib initialized.

2014-04-08T23:42:34.431+2:00 avvcbimage Info <16041>: VDDK:VixDiskLib: Initialize transport modes.

2014-04-08T23:42:34.431+2:00 avvcbimage Info <16041>: VDDK:VixDiskLib: Available transport modes: file:san:hotadd:nbdssl:nbd.

2014-04-08T23:42:34.431+2:00 avvcbimage Info <16041>: VDDK:VMware VixDiskLib (5.5) Release build-1556136

2014-04-08T23:42:34.451+2:00 avvcbimage Info <16041>: VDDK:VixDiskLibVim: VixDiskLibVim_Init: Initialization is completed.

2014-04-08T23:42:34.451+2:00 avvcbimage Info <9666>: Available transport modes are file:san:hotadd:nbdssl:nbd

2014-04-08T23:42:34.451+2:00 avvcbimage Info <16041>: VDDK:VixDiskLib: VixDiskLib_PrepareForAccess: Prepare to access disk.

2014-04-08T23:42:34.451+2:00 avvcbimage Info <16041>: VDDK:VixDiskLib: VixDiskLib_Connect: Establish connection.

2014-04-08T23:42:34.451+2:00 avvcbimage Info <16041>: VDDK:VixDiskLibVim: VixDiskLibVim_AllowVMotion: Disable VMotion.

2014-04-08T23:42:35.106+2:00 avvcbimage Info <17818>: VixDiskLib vMotion reservation successfully enabled by 'vSphere Data Protection'

2014-04-08T23:42:35.106+2:00 avvcbimage Info <16011>: Running cleanup of old backups.

2014-04-08T23:42:35.106+2:00 avvcbimage Info <16041>: VDDK:VixDiskLib: VixDiskLib_Cleanup: Remove previous mount points and clean up .

2014-04-08T23:42:35.106+2:00 avvcbimage Info <16041>: VDDK:VixDiskLib: VixDiskLib_Connect: Establish connection.

2014-04-08T23:42:35.106+2:00 avvcbimage Info <16041>: VDDK:VixDiskLib: VixDiskLib_Disconnect: Disconnect.

2014-04-08T23:42:35.106+2:00 avvcbimage Info <16048>: VixDiskLib_Cleanup() found no prior mounts to cleanup.

2014-04-08T23:42:35.131+2:00 avvcbimage Info <18664>: Login(https://vcenter.lab.local:443/sdk) Datacenter: 'Datacenter01'

2014-04-08T23:42:35.131+2:00 avvcbimage Info <0000>: - connected to 'VirtualCenter' - version: 'VMware vCenter Server 5.5.0 build-1623101', apiVersion:'5.5'

2014-04-08T23:42:35.154+2:00 avvcbimage Info <14692>: Login test is OK.

2014-04-08T23:42:35.762+2:00 avvcbimage Info <14644>: The VM '[QNAP02-Datastore201] CentOS QNAP Management Server/CentOS QNAP Management Server.vmx' has no old snapshots to delete.

2014-04-08T23:42:35.784+2:00 avvcbimage Info <14664>: no snapshots are present on this VM.

2014-04-08T23:42:35.784+2:00 avvcbimage Info <15994>: Logging into datacenter path of 'folder?dcPath=Datacenter01'

2014-04-08T23:42:35.943+2:00 avvcbimage Info <14673>: All Datastore Info:

datastore:'Local-hq-esx01 ' capacity=434865438720 free=425348562944

datastore:'QNAP02-Datastore201 ' capacity=2973996417024 free=2415045640192

2014-04-08T23:42:35.943+2:00 avvcbimage Info <14675>: All VM Info (7/7):

VM:'CentOS QNAP Management Server/ ' last modified on '08-Apr-2014 21:39'

VM:'vcenter.lab.local/ ' last modified on '08-Apr-2014 12:39'

VM:'vcenter/ ' last modified on '08-Apr-2014 13:11'

2014-04-08T23:42:36.038+2:00 avvcbimage Info <14677>: All VM file Info:

File:'CentOS QNAP Management Server-ctk.vmdk ' last modified on '05-Mar-2014 10:22' size=1049088

File:'CentOS QNAP Management Server-flat.vmdk ' last modified on '05-Mar-2014 10:22' size=17179869184

File:'CentOS QNAP Management Server.nvram ' last modified on '05-Mar-2014 10:22' size=8684

File:'CentOS QNAP Management Server.nvram.txt ' last modified on '30-Jan-2014 19:00' size=8684

File:'CentOS QNAP Management Server.vmdk ' last modified on '24-Feb-2014 15:49' size=620

File:'CentOS QNAP Management Server.vmsd ' last modified on '24-Feb-2014 15:49' size=43

File:'CentOS QNAP Management Server.vmx ' last modified on '08-Apr-2014 21:39' size=3004

File:'CentOS QNAP Management Server.vmx.txt ' last modified on '30-Jan-2014 19:00' size=2984

File:'CentOS QNAP Management Server.vmxf ' last modified on '08-Apr-2014 21:39' size=284

File:'vmware-2.log ' last modified on '29-Jan-2014 08:18' size=114456

File:'vmware-3.log ' last modified on '29-Jan-2014 08:44' size=122823

File:'vmware-4.log ' last modified on '29-Jan-2014 08:52' size=125758

File:'vmware-5.log ' last modified on '31-Jan-2014 11:44' size=154480

File:'vmware-6.log ' last modified on '31-Jan-2014 11:59' size=254378

File:'vmware-7.log ' last modified on '24-Feb-2014 15:37' size=148629

File:'vmware.log ' last modified on '05-Mar-2014 10:22' size=141769

2014-04-08T23:42:36.038+2:00 avvcbimage Info <14620>: Logging into datacenter 'vcenter.lab.local' with user 'vdpuser@LAB.LOCAL'

2014-04-08T23:42:36.216+2:00 avvcbimage Warning <0000>: No HTTP content was returned from datacenter from downloadFileData 'vcenter.lab.local'.

2014-04-08T23:42:36.216+2:00 avvcbimage Warning <17803>: Download VM .vmx file retry, count=0.

2014-04-08T23:42:41.269+2:00 avvcbimage Warning <0000>: No HTTP content was returned from datacenter from downloadFileData 'vcenter.lab.local'.

2014-04-08T23:42:41.269+2:00 avvcbimage Warning <17803>: Download VM .vmx file retry, count=1.

2014-04-08T23:42:46.389+2:00 avvcbimage Warning <0000>: No HTTP content was returned from datacenter from downloadFileData 'vcenter.lab.local'.

2014-04-08T23:42:46.389+2:00 avvcbimage Warning <17803>: Download VM .vmx file retry, count=2.

2014-04-08T23:42:51.389+2:00 avvcbimage Error <17804>: Max retries for downloading VM .vmx file exceeded, count=3.

2014-04-08T23:42:51.389+2:00 avvcbimage Error <17821>: failed to download vm metadata, try later

2014-04-08T23:42:51.390+2:00 avvcbimage Info <9772>: Starting graceful (staged) termination, failed to download vm metadata (wrap-up stage)

2014-04-08T23:42:51.390+2:00 avvcbimage Error <0000>: [IMG0009] createSnapshot: snapshot creation or pre/post snapshot script failed

2014-04-08T23:42:51.390+2:00 avvcbimage Error <0000>: [IMG0009] createSnapshot: snapshot creation/pre-script/post-script failed

2014-04-08T23:42:51.390+2:00 avvcbimage Info <9763>: snapshot created:false NOMC:false ChangeBlTrackingAvail:true UsingChBl:true

2014-04-08T23:42:51.390+2:00 avvcbimage Info <16041>: VDDK:VixDiskLib: VixDiskLib_EndAccess: Disk access completed.

2014-04-08T23:42:51.390+2:00 avvcbimage Info <16041>: VDDK:VixDiskLib: VixDiskLib_Connect: Establish connection.

2014-04-08T23:42:51.390+2:00 avvcbimage Info <16041>: VDDK:VixDiskLibVim: VixDiskLibVim_AllowVMotion: Enable VMotion.

2014-04-08T23:42:51.392+2:00 avvcbimage Info <16038>: Final summary, cancelled/aborted 0, snapview 1, exitcode 157: miscellaneous error

2014-04-08T23:42:51.929+2:00 avvcbimage Info <17819>: VixDiskLib vMotion reservation successfully released

--------------------------------------------------------------------------------------------------------

----- END avvcbimage log 2014-04-08 23:42:56 CEST (9 warnings, 4 errors, 0 fatal errors)

--------------------------------------------------------------------------------------------------------

*********** /usr/local/avamarclient/var-proxy-7/InitialTestBackup-1396993349036-514330c10e51fd762447275e43f5f51df0a8780b-1016-vmimagel.alg ***********

GSparks · ‎04-09-2014

Does the name of your VM, datastore, or cluster contain any of the following characters?

+ & @ % = # % * $ # ! \ / : * ? " < > | ; '

If so, try renaming to exclude the character.

-Greg Sparks

jhunter1 · ‎07-28-2014

Were you able to solve this issue? If yes, please provide details. Thank you.

LatinSuD · ‎09-08-2014

Same issue here. It happens with a couple of VM (out of dozens that work).

Neither VM name, datastore, cluster, path or file contain any special character.

jhunter1 · ‎09-08-2014

Please be sure to open a Support Request so that the issue can be tracked and hopefully resolved. make sure you are using the latest GA release of VDP (currently 5.5.6). Thank you.

LatinSuD · ‎09-09-2014

Nevermind I just found that my VDPA 5.5.6 is unable to perform backup of powered off machines. Yet another VDPA story to tell my grandsons...

jhunter1 · ‎01-16-2015

Stumbled across this again. Did you open a support request (SR) for the issue? If yes, can you provide that SR number? By the way, VDP should have no issues backing up powered off VMs - not sure why you are seeing that.

Thank you.

GSparks · ‎01-27-2015

2014-04-08T23:42:46.389+2:00 avvcbimage Warning <0000>: No HTTP content was returned from datacenter from downloadFileData 'vcenter.lab.local'.

2014-04-08T23:42:46.389+2:00 avvcbimage Warning <17803>: Download VM .vmx file retry, count=2.

2014-04-08T23:42:51.389+2:00 avvcbimage Error <17804>: Max retries for downloading VM .vmx file exceeded, count=3.

2014-04-08T23:42:51.389+2:00 avvcbimage Error <17821>: failed to download vm metadata, try later

These entries in the backup log may indicate the the ESXi host that the virtual machine is running on is having problems with an HTTP response.

Suggested flow for trying to resolve this would be:

1) Check the vCenter and verify that no ESXi hosts are in an "Unreachable", "Disconnected" or "Suspended" state. If they exist, reconnect them or remove them from the vCenter.

2) You can also test the connection by logging in to the vDP via SSH or Putty and then running the following commands:

2a) curl <ESXiHostFQDN>:902

The response should be similar to

220 VMware Authentication Daemon Version 1.10: SSL Required, ServerDaemonProtocol:SOAP, MKSDisplayProtocol:VNC , VMXARGS supported, NFCSSL supported

If the response is more similar to

authd: error while loading shared libraries: libcrypt.so.1: cannot map zero-fill pages: Error 28

This would indicate trouble with the ESXi host responding. You may need to restart the management services on the ESXi host in question.

NOTE : The following command will take the ESXi host offline temporarily. The VMs will be unreachable from vCenter during the restart period. However, the VMs will continue to run and be accessible from the network.

To restart Management services on the ESXi host:

Log into the ESXi host command line interface via SSH or Remote screen and issue the command

#services.sh restart

Once the ESXi host is back online, repeat the curl test above. If successful, then attempt an on-demand backup of the backups that were previously failing.

-Greg Sparks