Monday, 22 August 2016

Installation Of SQL Agent For VDP Fails.

When trying to install the SQL agent for vSphere Data Protection the agent installation fails with the error:

"VMware VDP for SQL Server Setup Wizard ended prematurely"

Here, under Installation directory:\Program files, there will be a directory called avp that would be created. This folder will have the logs which will contain the details regarding the failure. However, with the failure and roll back of the agent installation, this folder is removed automatically. So, the logs are lost. To gather the logs, we will have to redirect the msi installer logs to a different location.

To perform this run the below command: 
msiexec /i "C:\MyPackage\Example.msi" /L*V "C:\log\example.log"

The /i parameter will launch the MSI package. After the installation is finished, the log is complete.

Once the installation now fails, the above log file will have the logging for the cause of failure.
In my case, the following was noticed:

Property(S): UITEXT_SUPPORT_DROPPED = This release of the VMware VDP client software does not support the operating system version on this computer. Installing the client on this computer is not recommended.

The "EMC Avamar Compatibility and Interoperability Matrix" on EMC Online Support at provides client and operating system compatibility information.

So the failure here is due to unsupported Guest OS. The SQL version was 2014 which was very well supported. This SQL was running on a Windows 2012 R2 box.

From the VDP admin guide (Page 162), we see that SQL 2012 R2 is unsupported Guest OS for the client:

From the EMC Avamar Compatibility matrix (Page 38) we see this again is not supported. 

So, if you see such issues please verify if the Agent being installed is compatible with the Guest OS release. 

That's pretty much it!

Thursday, 18 August 2016

VDP Backup Fails: Failed To Download VM Metadata

A virtual machine backup was continuously failing with the error: VDP: Miscellaneous error.

When you look at the backup job log at the location:
# cd /usr/local/avamarclient/var

2016-08-18T08:24:59.099+07:00 avvcbimage Warning <40722>: The VM 'Win2012R2/' could not be located on the datastore:[FreeNAS-iSCSI] Win2012R2/Win2012R2.vmx
2016-08-18T08:24:59.099+07:00 avvcbimage Warning <40649>: DataStore/File Metadata download failed.
2016-08-18T08:24:59.099+07:00 avvcbimage Warning <0000>: [IMG0016] The datastore from VMX '[FreeNAS-iSCSI] Win2012R2/Win2012R2.vmx' could not be fully inspected.
2016-08-18T08:24:59.128+07:00 avvcbimage Info <0000>: initial attempt at downloading VM file failed, now trying by re-creating the HREF, (CURL) /folder/Win2012R2%2fWin2012R2.vmx?dcPath=%252fDatacenter&dsName=FreeNAS-iSCSI, (LEGACY) /fold

2016-08-18T08:25:29.460+07:00 avvcbimage Info <40756>: Attempting to Download file:/folder/Win2012R2%2FWin2012R2.vmx?dcPath=%252FDatacenter&dsName=FreeNAS%252DiSCSI
2016-08-18T08:25:29.515+07:00 avvcbimage Warning <15995>: HTTP fault detected, Problem with returning page from HTTP, Msg:'SOAP 1.1 fault: SOAP-ENV:Server [no subcode]
"HTTP Error"
Detail: HTTP/1.1 404 Not Found

2016-08-18T08:25:59.645+07:00 avvcbimage Warning <40650>: Download VM .vmx file failed.
2016-08-18T08:25:59.645+07:00 avvcbimage Error <17821>: failed to download vm metadata, try later
2016-08-18T08:25:59.645+07:00 avvcbimage Info <9772>: Starting graceful (staged) termination, failed to download vm metadata (wrap-up stage)
2016-08-18T08:25:59.645+07:00 avvcbimage Error <0000>: [IMG0009] createSnapshot: snapshot creation  or pre/post snapshot script failed
2016-08-18T08:25:59.645+07:00 avvcbimage Error <0000>: [IMG0009] createSnapshot: snapshot creation/pre-script/post-script failed
2016-08-18T08:25:59.645+07:00 avvcbimage Info <40654>: isExitOK()=157

Here we see that the backup is failing as it is unable to gather the vmx file details of the client it is trying to backup. It is unable to gather the vmx details is because it is unable to locate the client on the datastore. 

This issue occurs when the virtual machine files or the folder itself are manually moved to a different folder. 

If you look at the below screenshot, you see my virtual machine is under a folder called "do not power on"

Now, if you have a look the actual vmx file of this Windows2012R2 machine you see it is different.

From this, my virtual machine was initially under the FreeNAS-iSCSI / VM folder / VM Files and then this was moved to the "do not power on" folder. If you just move the virtual machine, the vmx file will not be updated with the new path. VDP during the backup will look at this path of the virtual machine and will fail because we do not have the vmx file in this location. 

To fix this, you will have to remove the virtual machine from the inventory and re-add it back to the inventory. Doing this will update the vmx file location as seen below. Once the correct location is populated you can run the backups for this virtual machine.

To register VM to inventory you can follow this KB article here.

That's pretty much it!

Tuesday, 16 August 2016

VDP Backup Fails: PAX stream append at sector offset 128 length 128 sectors=65536 failed (32)

So I have ran into this issue a couple of times now and was able to finally drill down to a solution, and so thought of sharing this as there is nothing about this issue anywhere on the web.

In the few scenarios where I came across this issue, some were due to expanding the VMDK causes the backup to fail, backup for VM with a disk greater than 2 TB fails and sometimes without any reason it fails continuously.

This failure occurs prominently when:

1) VMDK is larger than 2 TB. 
2) VMDK is not an integral multiple of 1 MB. 
3) VMDK has changes in the last extent of the VMDK

Let's see what time means a little down the line.

To start off, when you open the backup job log to see for a failure, you will see the following: 


2016-07-25T20:50:48.091+04:00 avvcbimage Info <14700>: submitting pax container in-use block extents:
2016-07-25T20:50:48.221+04:00 avvcbimage Info <6688>: Process 9604 (/usr/local/avamarclient/bin/avtar) finished (code 176: fatal signal)
2016-07-25T20:50:48.221+04:00 avvcbimage Error <0000>: [IMG0010] PAX stream append ([Store_1] test/test.vmdk) at sector offset 128 length 128 sectors=65536 failed (32)
2016-07-25T20:50:48.221+04:00 avvcbimage Warning <6690>: CTL workorder "Test-backup-1469491200006" non-zero exit status 'code 176: fatal signal'
2016-07-25T20:50:48.221+04:00 avvcbimage Info <9772>: Starting graceful (staged) termination, PAX stream append failed (wrap-up stage)
2016-07-25T20:50:48.221+04:00 avvcbimage Info <40654>: isExitOK()=157 
2016-07-25T20:50:48.221+04:00 avvcbimage Info <16022>: Cancel detected(miscellaneous error), isExitOK(0).
2016-07-25T20:50:48.221+04:00 avvcbimage Info <9746>: bytes submitted was 65536
2016-07-25T20:50:48.221+04:00 avvcbimage Error <0000>: [IMG0010] pax_container::endfile(virtdisk-flat.vmdk,65536) returned problem:32
2016-07-25T20:50:48.221+04:00 avvcbimage Error <0000>: [IMG0010] pax_container::enddir returned problem:32
2016-07-25T20:50:48.222+04:00 avvcbimage Info <40654>: isExitOK()=157 
2016-07-25T20:50:48.222+04:00 avvcbimage Info <16022>: Cancel detected(miscellaneous error), isExitOK(0).
2016-07-25T20:50:48.222+04:00 avvcbimage Info <12032>: backup (Store_1] test/test.vmdk) terminated 3145728.00 MB
2016-07-25T20:50:48.222+04:00 avvcbimage Info <40654>: isExitOK()=157 
2016-07-25T20:50:48.222+04:00 avvcbimage Error <0000>: [IMG1003] Backup of [Store_1] test/test.vmdk failed
2016-07-25T20:50:48.222+04:00 avvcbimage Info <16041>: VDDK:VixDiskLib: VixDiskLib_Close: Close disk.

The avtar.log for this backup job in the same directory has the following back trace.

2016-08-08T20:42:17.180+04:00 avtar FATAL <5889>: Fatal signal 11 in pid 28769
> 2016-08-08T20:42:17.186+04:00 [avtar]  FATAL ERROR: <0001> uapp::handlefatal: Fatal signal 11
> 2016-08-08T20:42:17.186+04:00 [avtar]  | 0000000000b3abe1
> 2016-08-08T20:42:17.186+04:00 [avtar]  | 0000000000b3b957
> 2016-08-08T20:42:17.186+04:00 [avtar]  | 0000000000b3bc7b
> 2016-08-08T20:42:17.186+04:00 [avtar]  | 0000000000b3bd6e
> 2016-08-08T20:42:17.186+04:00 [avtar]  | 0000000000a86530
> 2016-08-08T20:42:17.186+04:00 [avtar]  | 00007f9388482850
> 2016-08-08T20:42:17.186+04:00 [avtar]  | 0000000000ac7364
> 2016-08-08T20:42:17.186+04:00 [avtar]  | 00000000006762ef
> 2016-08-08T20:42:17.186+04:00 [avtar]  | 0000000000678363
> 2016-08-08T20:42:17.186+04:00 [avtar]  | 00000000006c8db8
> 2016-08-08T20:42:17.186+04:00 [avtar]  | 00000000006cc683
> 2016-08-08T20:42:17.186+04:00 [avtar]  | 00000000006cd083
> 2016-08-08T20:42:17.186+04:00 [avtar]  | 00000000009a5b76
> 2016-08-08T20:42:17.186+04:00 [avtar]  | 00000000009ad0ed
> 2016-08-08T20:42:17.186+04:00 [avtar]  | 0000000000612bce
> 2016-08-08T20:42:17.186+04:00 [avtar]  | 00000000006c1492
> 2016-08-08T20:42:17.186+04:00 [avtar]  | 00000000006c36b6
> 2016-08-08T20:42:17.186+04:00 [avtar]  | 00000000004cfcfb
> 2016-08-08T20:42:17.186+04:00 [avtar]  | 00000000004d6d4e
> 2016-08-08T20:42:17.186+04:00 [avtar]  | 00000000004d82e0
> 2016-08-08T20:42:17.186+04:00 [avtar]  | 0000000000a88129
> 2016-08-08T20:42:17.186+04:00 [avtar]  | 00000000004ea627
> 2016-08-08T20:42:17.186+04:00 [avtar]  | 00007f93864b1c36
> 2016-08-08T20:42:17.186+04:00 [avtar]  | 000000000048a029
> 2016-08-08T20:42:17.186+04:00 [avtar]  ERROR: <0001> uapp::handlefatal: aborting program pid=28769, sig=11
> 2016-08-08T20:42:17.186+04:00 avtar FATAL <5890>: handlefatal: Aborting program with code 176, pid=28769, sig=11

So I had one disk for this VM which was expanded beyond 2 TB and when converted into MB it was 3397386.24 MB (3.24 TB). In plain words, the format in MB is fractional and not a whole number and hence it is not an integral multiple of 1. 
When your VDP sees the disk as a fractional value and beyond 2 TB, the backup fails. This is a known issue in the avTar version running on VDP. 

To find your current avTar version you can run the following;

> This command from root of the VDP SSH

> These two commands from admin mode only of VDP SSH
gsan --version --version

A VDP 6.1 has an avTar version of 7.2 with a varying minor build. 

How do we resolve this? 

Step 1: For a quick backup to make sure everything is saved for this VM. Not recommended as a permanent solution. 

Disable CBT on the VM, so that incremental backups are disabled for this VM and all backups are always full backup. If you do not have a restore point for a long time and would badly need one, then you can implement this. Else, if you have a good known restore point, then this is not required as it unnecessarily consumes space. To disable CBT you can follow this VMware KB article here

Step 2: Recommended. Make sure a good backup is available before this.

Here, you will have to locate the sizes of all your disks for that VM and convert them to MB. If the converted value in MB is a whole number, then that disk is good to go. 

If not, like in my case, where the drive was 3397386.24 MB, then we will have to round off this drive to the next largest whole number. Here it would be 3397387 MB. You can do this from the edit settings of the virtual machine. There is no need of expanding the drive from within the guest. This is done on the VMDK level only so that the VDP can look at this drive as an integral multiple of 1. 

Post this, you can have incremental backups running. 

This is acknowledged as a known issue and the fix is in the future release of VDP. Release version and ETA are unknown currently.

If you have questions before implementation, let me know.


Wednesday, 3 August 2016

VDP Automatic Backup Verification Fails With VMware Tools Heartbeat Timeout

So recently I was working on a colleague's case where the backup verification, both manual and automatic were failing with VMware tools timeout. Now, there were multiple restore points being verified here and only one of them was failing. The VDP admin guide for verification states the below:

"Set the heartbeat timeout interval to its optimal value, depending on the environment. Note that some VMs may take longer to send and receive the VMware Tools heartbeat than others"

On the verification job logs, the following was observed. " >> " Marks the explanation of the event:

2016-07-14T21:52:10.541-02:00 avvcbimage Info <19672>: vmAction powerOnVM()
>> The VM power On function is called

2016-07-14T21:52:10.549-02:00 avvcbimage Info <17787>: Modifying E1000 adapter: Network adapter 1 to not Connect at Power On
>> The network adapter is disconnected on power on to avoid IP conflict 

2016-07-14T21:52:17.665-02:00 avvcbimage Info <14632>: VM '[virtual_machines1] VDP_VERIFICATION_camserver_1468522800276/VDP_VERIFICATION_camserver_1468522800276.vmx' Power On task completed, moref=
>> VM is powered ON 

2016-07-14T21:52:17.665-02:00 avvcbimage Info <19674>: vmAction waitforToolRunning()
>> Waiting for heartbeat verification

2016-07-14T21:57:22.177-02:00 avvcbimage Warning <19675>: wait for toolrunning is timed out or cancelled
>> Verification timed out

2016-07-14T21:57:22.178-02:00 avvcbimage Info <19685>: vmAction poweroffVM()
>> power off VM function is called

2016-07-14T21:57:25.225-02:00 avvcbimage Info <14632>: VM '[virtual_machines1] VDP_VERIFICATION_camserver_1468522800276/VDP_VERIFICATION_camserver_1468522800276.vmx' Power Off task completed, moref=
>> power off completed

2016-07-14T21:57:25.225-02:00 avvcbimage Info <19686>: vmAction deleteVM()
>> delete VM function is called

2016-07-14T21:57:28.295-02:00 avvcbimage Info <14632>: VM '[virtual_machines1] VDP_VERIFICATION_camserver_1468522800276/VDP_VERIFICATION_camserver_1468522800276.vmx' deletion task completed, moref=
>> VM is deleted successfully

2016-07-14T21:57:28.311-02:00 avvcbimage Error <19702>: ABV failed
>> Automatic backup verification failed. 

So, there is a parameter that we need to add in the avvcbimageAll.cmd file to increase the heartbeat wait timeout for the appliance.

The steps would be:

1. Open a SSH to the VDP appliance
2. Browse to the following directory
# usr/local/avamarclient/var/avvcbimageAll.cmd
3. Open this file in a vi editor and add the following parameter:
4. Save the file and restart the avagent daemon using the below command:
service avagent-vmware restart

Post this, the VDP appliance will wait for 20 minutes for VM tools heartbeat to be received before it could time out.
If the tools validation complete before 20 minutes, then it will proceed to the next steps. So setting the timeout to a large value will not have any performance impact on the VMs which are not facing the VM tools timeout during verification.

Simple, yes!