Auditing VMware backups

A customer asked me to report on whether every virtual machine in their VMware environment was getting backed up.

HP Data Protector includes a report on the last successful backup for various objects, but it doesn’t provide a convenient way of tying that in with what is on a VMware cluster.

So I wrote a program, imaginatively called vm-backup-audit.pl. You can get a copy from http://www.ifost.org.au/dataprotector/software/vm-backup-audit.pl

This program queries the vcenter-server given as a command-line argument, and identifies all the virtual machines on that server. It uses the VMware Perl SDK to do this (there's a program called vidiscover.pl which is makes use of.)

It also queries the Data Protector internal database for the last 14 days to find out what objects have been backed up during VEAgent backups. It then prepares a list of virtual machine names and shows when they were last (successfully or unsuccessfully) backed up. 


If the virtual machine has never been backed up successfully in the time frame , the message no full backup completed cleanly will be shown. Otherwise, the relevant session IDs will be shown in reverse chronological order.
This is the kind of output it gives:

[LaptopDatacenter:linuxvm1] 2014/12/29-6 (Full) 2014/12/29-5 (Incremental)
[LaptopDatacenter:unbacked-up-vm] <no full backup completed cleanly>
[LaptopDatacenter:linuxvm3] 2014/12/29-6 (Failed Full) 2014/12/29-5 (Incremental) 2014/12/28-1 (Full)

In full honesty, there are some obvious short-comings:

• It doesn’t correctly handle two virtual machines with the same name in the same data center. This is probably impossible anyway, so doesn’t matter. If they are in different data centers it is able to distinguish them.
• It’s not smart enough to understand that a virtual machine might be getting cloned or replicated between data centres.
• It might not cope very well with mixed Hyper-V and VMware environments. It might not cope very well with two instances running simultaneously.
• It has only been tested on a version 9.02 Linux-based cell console, talking to a Windows cell manager. It won't be hard to get working on anything else, but I just haven't done it yet.

If these matter to you and have a budget to cover fixing any of these, please get in touch and I'll see what I can do.

Greg Baker is an independent consultant who happens to do a lot of work on HP DataProtector. He is the author of the only published books on HP Data Protector (http://www.ifost.org.au/press/#dp). He works with HP and HP partner companies to solve the hardest big-data problems (especially around backup). See more at IFOST's DataProtector pages at http://www.ifost.org.au/dataprotector

VMware, Changed Block Tracking, disk expansion and silent backup corruption

VMware have released this Knowledge Base article.

http://kb.vmware.com/selfservice/microsites/search.do?language=en_US&cmd=displayKC&externalId=2090639

If you have Change Block Tracking turned on (which is a sensible thing to do) and then you expand a virtual disk to be larger than 128GB, the data provided to the backup provider is wrong.

I haven't verified this with Data Protector, but I can't see any reason why DP wouldn't be affected in the same way as (say) Veeam, which uses the same mechanism.

Solution: turn off change block tracking, run a backup, and then turn change block tracking on again.

Greg Baker is an independent consultant who happens to do a lot of work on HP DataProtector. He is the author of the only published book on HP Data Protector (http://x.ifost.org.au/dp-book). He works with HP and HP partner companies to solve the hardest big-data problems (especially around backup). See more at IFOST's DataProtector pages at http://www.ifost.org.au/dataprotector

Data Protector 9.0 released

Normally the first I see of a new release is when it appears for evaluation on
http://www.hp.com/go/dataprotector but version 9 seems to have been released to customers on support contracts first.

The release notes are quite brief: nearly everything that has been announced as "new in version 9" was already available in the patches that took version 8.12 (Windows / Linux ). Integration with DataDomain, for instance.

The only obviously new option for most customers is that there is a new kind of backup-to-disk device ("Smart Cache") which you can use for VMware VEAgent backups. Then you can use the VMware GRE (Granular Recovery Extension) to extract out individual files from the Smart Cache device without having to restore the whole virtual disk first. This is obviously a big win for backing up virtual machines with large disks: it won't be necessary to do a file-level backup and a VMware backup.

Customers with large B6200 / B6500 arrays might find the federated de-duplication option useful because it means you don't have to assign engines to particular devices.


Greg Baker is an independent consultant who happens to do a lot of work on HP DataProtector. He is the author of the only published book on HP Data Protector (http://x.ifost.org.au/dp-book). He works with HP and HP partner companies to solve the hardest big-data problems (especially around backup). See more at IFOST's DataProtector pages at http://www.ifost.org.au/dataprotector

VMware, Data Protector and virtual machines which won't consolidate

Working on a customer's systems recently,  there were a large number of virtual machines with the following error message:

Configuration Issues
Virtual machine disks consolidation is needed.

But if I tried to right-click in vCenter and select Snapshots -> Consolidate, what I got was "unable to access file <unspecified filename> since it is locked".

This was also causing error messages in the backup log, because HP Data Protector attempts to consolidate disks at the start of a full backup.

The VMware KB articles suggested various things to identify the lock. I ssh'ed in and ran

tail -f vmware.log | grep lock

to identify what the lock could be. As it turned out, it wasn't quite a lock. The file that couldn't be opened was a .vmdk file - no surprises there. So I ran

lsof | grep the-vmdk-file

This showed that two different processes had it open.

ps | grep process-id-from-the-previous-step

showed that the two processes were both /bin/vmx, but it was possible to distinguish them by their child vmx-vthread processes.

One of them was the process running the virtual machine (no surprises there), and the other was a process belonging to the hostname of the computer that runs their HP DataProtector VEPA agent.

This customer has a virtual machine inside their VMware environment which runs their VMware backups. They don't have to worry about correctly presenting LUNs or having an extra device attached to their SAN fabric. They do source-side deduplicated backups from this virtual machine, so it doesn't generate as much network traffic as it otherwise would.

What had happened was that some backup had failed spectacularly leaving the snapshots mounted on the VEPA agent virtual machine. Looking at the settings for the agent virtual machine it proudly said that it had 13 virtual disks - when it should only have had one, its boot disk.

Naturally, VMware couldn't consolidate the snapshots because as far as it was concerned, those snapshots were still in use. VMware also couldn't delete the virtual disks off the agent machine either, because there were snapshots depending on them.

So the solution was:

• Remove the snapshots on the agent machine.
• Remove the extraneous disks from the agent machine.
• Run the snapshot consolidation from the vCenter GUI.

When VMware NBD and NBDSSL backups fail

I was working on some VMware backups when I ran into this strange sequence of messages: a backup which is showing that that is quite possible to backup a VMX file, but not the VMDK files. And the error messages in the session aren't very informative!

[Normal] From: BSM@cell-manager.ifost.org.au "NBD test backup"  Time: 19/05/2014 10:30:16 AM
        Backup session 2014/05/19-5 started.

[Normal] From: BSM@cell-manager.ifost.org.au "NBD test backup"  Time: 19/05/2014 10:30:16 AM
        OB2BAR application on "vepa-agent.ifost.org.au" successfully started.

[Normal] From: VEPALIB_VMWARE@vepa-agent.ifost.org.au "/DC"  Time: 19/05/2014 10:30:17 AM
        Resolving objects for backup on vCenter 'vcenter.ifost.org.au' ... 

[Normal] From: VEPALIB_VMWARE@vepa-agent.ifost.org.au "/DC"  Time: 19/05/2014 10:30:33 AM
        Add Virtual Machine to the backup ... 
                Name: VM1
                Path: /DC/Discovered virtual machine/VM1
                InstanceUUID: 52dbf234-252e-c5dd-9df5-51c304bcf312

[Normal] From: VEPALIB_VMWARE@vepa-agent.ifost.org.au "/DC"  Time: 19/05/2014 10:30:35 AM
        Virtual Machine 'VM1': Locking vMotion ... 

[Warning] From: VEPALIB_VMWARE@vepa-agent.ifost.org.au "/DC"  Time: 19/05/2014 10:30:35 AM
         Virtual Machine 'VM1': vMotion is in Progress.

[Warning] From: VEPALIB_VMWARE@vepa-agent.ifost.org.au "/DC"  Time: 19/05/2014 10:31:08 AM
        Virtual Machine 'VM1': Could not lock vMotion.

Everything's pretty much fine. There are lots of reasons for a vMotion lock to fail.

[Normal] From: VEPALIB_VMWARE@vepa-agent.ifost.org.au "/DC"  Time: 19/05/2014 10:31:13 AM
        Creating folder /var/opt/omni/tmp/55fd5af8-f853-403e-bedf-2d1e60e418dd ... 

[Normal] From: VEPALIB_VMWARE@vepa-agent.ifost.org.au "/DC"  Time: 19/05/2014 10:31:19 AM  
        Virtual Machine 'VM1': Backing up configuration file VM1.vmx ... 

[Normal] From: VEPALIB_VMWARE@vepa-agent.ifost.org.au "/DC"  Time: 19/05/2014 10:31:20 AM
        Virtual Machine 'VM1': Creating snapshot ... 

[Normal] From: VEPALIB_VMWARE@vepa-agent.ifost.org.au "/DC"  Time: 19/05/2014 10:31:59 AM
        Virtual Machine 'VM1': Optimizing disk scsi0:0 ... 

[Normal] From: VEPALIB_VMWARE@vepa-agent.ifost.org.au "/DC"  Time: 19/05/2014 10:32:00 AM
        Virtual Machine 'VM1': Backing up VSS manifest  VM1/VM1-vss_manifests11.zip.

And now for the interesting part:

[Major] From: VEPALIB_VMWARE@vepa-agent.ifost.org.au "/DC"  Time: 19/05/2014 10:33:15 AM
        Virtual Machine 'VM1': Could not backup disk scsi0:0 ... 

[Major] From: VEPALIB_VMWARE@vepa-agent.ifost.org.au "/DC"  Time: 19/05/2014 10:33:15 AM
[172:162]       Virtual Machine 'VM1': No disk backed up ... 

[Critical] From: VEPALIB_VMWARE@vepa-agent.ifost.org.au "/DC"  Time: 19/05/2014 10:33:15 AM
        Backup of object failed.
                Name: VM1
                Path: /DC/Test_VMs/VM1
                InstanceUUID: 52dbf234-252e-c5dd-9df5-51c304bcf312

[Normal] From: VEPALIB_VMWARE@vepa-agent.ifost.org.au "/DC"  Time: 19/05/2014 10:33:16 AM
        Virtual Machine 'VM1': Removing snapshot ... 

[Normal] From: VEPALIB_VMWARE@vepa-agent.ifost.or.gau "/DC"  Time: 19/05/2014 10:33:24 AM
        Virtual Machine 'VM1': Unlocking vMotion ... 

Deleted directory /var/opt/omni/tmp/564d01b7-7910-97a0-d54d-85c11ff8becd-vm-58/nbd
Deleted directory /var/opt/omni/tmp/564d01b7-7910-97a0-d54d-85c11ff8becd-vm-58/nbdssl
Deleted directory /var/opt/omni/tmp/564d01b7-7910-97a0-d54d-85c11ff8becd-vm-58/hotadd

[Normal] From: BSM@cell-manager.ifost.org.au "NBD test backup"  Time: 19/05/2014 10:33:53 AM
        OB2BAR application on "vepa-agent.ifost.org.au" disconnected.

I've truncated the rest of the messages.
Turning up the debugging level, the debug logs showed this:

[110] [VddkUtil::diskLibLog] NBD_ClientOpen: attempting to create connection to vpxa-nfcssl://[ESXi-MGMT-VMFS-1] VM1/VM1.vmdk@esxi1.ifost.org.au:902

[110] [VddkUtil::diskLibLog] Started up WSA

[110] [VddkUtil::diskLibLog] CnxOpenTCPSocket: Cannot connect to server esxi1.ifost.org.au:902: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond

[110] [VddkUtil::diskLibLog] CnxAuthdConnect: Returning false because CnxAuthdConnectTCP failed

[110] [VddkUtil::diskLibLog] CnxConnectAuthd: Returning false because CnxAuthdConnect failed

[110] [VddkUtil::diskLibLog] Cnx_Connect: Returning false because CnxConnectAuthd failed

[110] [VddkUtil::diskLibLog] Cnx_Connect: Error message: Failed to connect to server esxi1.ifost.org.au:902

[ 20] [VddkUtil::diskLibWarning] [NFC ERROR] NfcNewAuthdConnectionEx: Failed to connect to peer. Error: Failed to connect to server esxi1.ifost.org.au:902

[110] [VddkUtil::diskLibLog] NBD_ClientOpen: Couldn't connect to esxi1.ifost.org.au:902 Failed to connect to server esxi1.ifost.org.au:902

The clue is the failed connection to esxi1.ifost.org.au. The VEPA backup agent obviously has to connect to the Vcenter server in order to start a backup, but because there was no SAN connectivity between the VEPA agent and the LUNs supporting the VM1 virtual machine's VMDK files, the VEPA agent ends up having to talk to the ESX server directly as well.

There can be many reason for this connection to fail: a firewall could be blocking the connection between the vepa agent and the esx server. Or in this case, there was no DNS entry for esxi.ifost.org.au didn't exist.


Greg Baker is an independent consultant working on HP DataProtector, LiveVault and many other technologies. He is the author of the only published book on HP Data Protector (http://x.ifost.org.au/dp-book). See more at IFOST's DataProtector pages at http://www.ifost.org.au/dataprotector

When debug logs aren't good enough

Normally, when you want to get more information about what is going on inside a HP Data Protector process, you simply turn on debugging: edit /opt/omni/.omnirc on Linux/Unix or C:\ProgramData\Omniback\omnirc on Windows and add a line:

OB2DBG=1-200 myproblemname.txt

All processes read this file when they start. You might want to be aware of OB2DBG_DIR so that you can direct the (massive) files somewhere with a lot of room. (For example, if you put your debug logs onto the same drive as your internal database, you might start getting internal database errors because you have run out of disk space.)

And generally, there's more than enough information in there to figure out what's going on.

But this week, I hit something a bit more obscure. I had a VEAgent backup (which was supposed to be backing up VMware) hang very early in the session. Even more bizarrely, it was hanging before it even initiated a connection to the VSphere server.

The debug logs were uninformative. I really need to know what it was hanging on.

Fortunately, almost all processes running on cell clients (i.e. almost everything that isn't part of the cell manager's infrastructure) are launched from either the Windows omniinet process or inetd or xinetd on Linux / Unix. The main exception is the StoreOnce processes, which start at boot time.

I was able to reproduce the hang on both the initial discovery (when you try to browse for a backup) and starting an actual backup, so I decided to focus on the initial discovery first, which is done by the vepa_util.exe process. (It's even got the .exe ending on Linux!)

So I move the vepa_util.exe process out of the way...

mv /opt/omni/lbin/vepa_util.exe /opt/omni/lbin/vepa_util.exe.bin

And then created the following replacement:

#!/bin/bash 

exec strace -f -ff -o /tmp/tracelog \ 

        /opt/omni/lbin/vepa_util.exe.bin $*

This script instead launches the original binary (with all command-line arguments) under strace, where each trace file gets the PID of the traced process appended to its filename.

Then I tried to start creating another backup. The GUI froze, as before, but this time I could look at the last line of the trace file to know which system call was blocking.

read(10,

Reading from file descriptor 10. But what was file descriptor 10? A quick lsof -p command on the vepa_util.exe process ID turned up a socket connection back to the cell manager:

vepa_util.exe ....  TCP vmclient:52395->cellmanager:2315

And even more curiously, when I logged into the cell manager and looked at the socket there, there were bytes waiting to be sent: the send-queue (send-Q in netstat) wasn't empty.

It turned out to be a firewalling issue (which I'll try to blog about later), but there would have been no way of seeing that from the Data Protector debug logs.

Greg Baker is an independent consultant working on HP DataProtector, LiveVault and many other technologies. He is the author of the only published book on HP Data Protector (http://x.ifost.org.au/dp-book) See more at IFOST's DataProtector pages at http://www.ifost.org.au/dataprotector