Question VMware backup (failing Error 23)

[mmeeggaann]

In order to backup VMware virtual machines, is it  necessary to set up  the FQDN of the ESX server?

I have a ESX 4 standalone server (no administered by a vCenter), but is not added to the DNS. So Im able to added to NBU by Ip address only even when I  added the entry to the hosts file.

As a result the VM backup failed with Error 23, Error to opening the snapshot disks using given transport mode.

In the VxMS I found the lines:

 SSLVerifyCertAgainstSystemStore: Subject mismatch: hostname. vs IP address

        08/15/2011 20:28:12.0140 [TID 0x0001bc54]: g_vdInterfaceLogger:.\libvix.cpp:1693 <VFM_ESWARN> : SSLVerifyCertAgainstSystemStore: The remote host certificate has these problems:

* The host name used for the connection does not match the subject name on the host certificate

* The host certificate chain is not complete.

Any ideas?

[pikachu]

I am assuming the child job is failing. If so... that means you actually got a status code 6.

Are you backing up over the SAN? NBD? HotADD?

What version of NBU/VC/ESX are you running?

[mmeeggaann]

Yes the child job is failing, in a second post I'll confirm you the status code  because I have to verify it.

NBU 7.0.1

vSphere 4 Enterprise

nbd transport mode

Thanks :)

[pikachu]

Do you have any vmware rollup patches installed?

The eeb is: 2105102

Also let me know IF you have it installed... at patch version it is.

You can ignore:

 SSLVerifyCertAgainstSystemStore: Subject mismatch: hostname. vs IP address

        08/15/2011 20:28:12.0140 [TID 0x0001bc54]: g_vdInterfaceLogger:.\libvix.cpp:1693 <VFM_ESWARN> : SSLVerifyCertAgainstSystemStore: The remote host certificate has these problems:

Increase vxms logging to hex 7580. Clean out the vxms log folder. Re-run the job and re-post it.

Also does the backup work if you backup through the ESX directly?

[mmeeggaann]

You're right. The backup job is failing with the status code 6.

I re-check...  the version of VMware ESX is 4.1.0 , 260247

About the transport mode is ndb, but I already test with the "try all types" option.

The snapshots creation is working welll, the error is with the child job at the time to read 

What do you mean about "backup through the ESX directly"'?

I increased VxMS logging to hex 7580 and re-run the job:

08/17/2011 17:32:04.0519 [TID 0x0001c378]: VixInterface::vdOpen:.\VixInterface.cpp:198 <VFM_ESERROR> [Sys Error: No error] : VixDiskLib_Open() error. Exited

        08/17/2011 17:32:04.0519 [TID 0x0001c378]: VixGuest::openLeafSnapshotDisks:.\VixGuest.cpp:436 <VFM_ESERROR> [Sys Error: No error] : vdOpen() error = 13. Calling closeLeafSnapshotDisks()

        08/17/2011 17:32:04.0519 [TID 0x0001c378]: VixGuest::openLeafSnapshotDisks:.\VixGuest.cpp:539 <VFM_ESERROR> [Sys Error: No error] : Exited with failure

        08/17/2011 17:32:04.0519 [TID 0x0001c378]: VixCoordinator::vixMapObjCtl:.\VixCoordinator.cpp:904 <VFM_ESERROR> [Sys Error: No error] : Exited with 23

        08/17/2011 17:32:04.0519 [TID 0x0001c378]: vix_map_objctl:.\libvix.cpp:1145 <VFM_ESERROR> [Sys Error: No error] : Error 23

End vfm_objctl: result(23)

        08/17/2011 17:32:04.0519 [TID 0x0001c378]: VixManager::closeGuest:.\VixManager.cpp:90 <VFM_ESINFO> : Guest has no open file systems hence deleting it

        08/17/2011 17:32:04.0519 [TID 0x0001c378]: VixGuest::~VixGuest:.\VixGuest.cpp:105 <VFM_ESINFO> : Entered

        08/17/2011 17:32:04.0566 [TID 0x0001c378]: VixGuest::~VixGuest:.\VixGuest.cpp:214 <VFM_ESINFO> : Cleaned up VM State files

        08/17/2011 17:32:04.0566 [TID 0x0001c378]: VixGuest::~VixGuest:.\VixGuest.cpp:235 <VFM_ESINFO> : Exited

Thanks.

[pikachu · Accepted solution]

What do you mean about "backup through the ESX directly"'?

=> My bad... you are using a stand alone ESX server.

Anyway you could post the entire VxMS log?

If you didn't introduce the datastore luns over san/iscsi to the backup host, try all types doesn't help. Just keep it on NBD.

In the policy try to disable EXCLUDE WHITE SPACES and disable QUIESCING.

[Rick_Brown]

I have 3 machines randomly doing this same sort of thing. They don't fail everytime but when they do, we can usually just re-run the backup & it works successfully. Very odd becasue we do over 1k SQL backups per day. Yet these 3 VM's have something different about them, all are running NBU 7.0.1.

These are running a 32bit version SQL2005 as a VM. At first we thoguht it was a memory issue, so we added more but the issue persists. I have a case open with Symantec for this, but I'm waiting to capture a failure with the logging jacked up to 5 - it's like fishing & waiting for the big one to strike.

[mmeeggaann]

I set the Policy as follow and re-run the backup:

Perform block level incremental backups: not selected

*Client name selection:  VM hostname

*Virtual machine backup: Mapped full VM backup

*Transfer type: nbd 

*Virtual machine quiesce: disabled (before enabled)

*Exclude unused and deleted blocks: disabled (before enabled)

*Existing snpashot handing: Remove NBU

Great! the backup is running now, it began to write :)

Now, I'll test to know which of the 2 paramters is helping the backup works.

I would like to enable the VM quiesce paramter to guaratee the integrity of the data.

Let me test, I would let you know the results

[mmeeggaann]

Here the results:

• The job failed

*Client name selection:  VM hostname

*Virtual machine backup: Mapped full VM backup

*Transfer type: nbd 

*Virtual machine quiesce: Enabled

*Exclude unused and deleted blocks: disabled 

*Existing snpashot handing: Remove NBU

• The backup ran successfully  

*Client name selection:  VM hostname

*Virtual machine backup: Mapped full VM backup

*Transfer type: nbd 

*Virtual machine quiesce: Disabled

*Exclude unused and deleted blocks: Enabled 

*Existing snpashot handing: Remove NBU

I would like to find the cause, because I think is important to quiesce the VM to back them up.

I attach the VxMS log of the 1st try (Quiesce enabled) when the job failed.

Begin VxMS Session...

Logmask set to 0x0

Current Environment Variables

VFM_ROOT = NULL

VFM_PRIVATE_ROOT = NULL

VFM_MAP_API_LIB = NULL

VFM_MAP_DIR = NULL

VFM_UTIL_LIB = NULL

Begin: vfm_open_id [08/17/11 14:57:07]

  Input Parameters:

  flags=524291

  context=NULL

  origobjid=NULL

   [ Objid ]

     vfm_objid_t { 

       vid_length = 206

objid->vid_name[E:\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.Z1T3MXMYV02.dominio_1313610938.0.NBU_DATA.xml] is of length objid->vid_len = 206!!

       vid_type = 0

     }

        08/17/2011 19:57:07.0282 [TID 0x00019f1c]: vhd_map_init:.\libvhd.cpp:798 <VFM_ESINFO> : Entered

        08/17/2011 19:57:07.0282 [TID 0x00019f1c]: vhd_map_init:.\libvhd.cpp:817 <VFM_ESINFO> : Exited

        08/17/2011 19:57:07.0282 [TID 0x00019f1c]: VhdCoordinator::vhdMapInit:.\VhdCoordinator.cpp:640 <VFM_ESINFO> : Entered

        08/17/2011 19:57:07.0282 [TID 0x00019f1c]: VhdCoordinator::vhdMapInit:.\VhdCoordinator.cpp:679 <VFM_ESINFO> : Exited

        08/17/2011 19:57:07.0282 [TID 0x00019f1c]: vhd_map_claim_id:.\libvhd.cpp:224 <VFM_ESINFO> : Entered

        08/17/2011 19:57:07.0282 [TID 0x00019f1c]: vhd_map_claim_id:.\libvhd.cpp:227 <VFM_ESINFO> : Objid: E:\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.Z1T3MXMYV02.dominio_1313610938.0.NBU_DATA.xml

        08/17/2011 19:57:07.0282 [TID 0x00019f1c]: vhd_map_claim_id:.\libvhd.cpp:246 <VFM_ESINFO> : Exited

        08/17/2011 19:57:07.0282 [TID 0x00019f1c]: VhdCoordinator::vhdMapClaimId:.\VhdCoordinator.cpp:157 <VFM_ESINFO> : Entered

        08/17/2011 19:57:07.0282 [TID 0x00019f1c]: VhdCoordinator::vhdMapClaimId:.\VhdCoordinator.cpp:159 <VFM_ESINFO> : Objid: E:\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.Z1T3MXMYV02.dominio_1313610938.0.NBU_DATA.xml

        08/17/2011 19:57:07.0282 [TID 0x00019f1c]: VhdManager::claimId:.\VhdManager.cpp:178 <VFM_ESINFO> : Entered

        08/17/2011 19:57:07.0282 [TID 0x00019f1c]: VhdManager::claimId:.\VhdManager.cpp:180 <VFM_ESINFO> : Objid: E:\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.Z1T3MXMYV02.dominio_1313610938.0.NBU_DATA.xml

        08/17/2011 19:57:07.0282 [TID 0x00019f1c]: VhdManager::claimId:.\VhdManager.cpp:224 <VFM_ESINFO> : Exited

        08/17/2011 19:57:07.0282 [TID 0x00019f1c]: VhdManager::claimHyperVGuestId:.\VhdManager.cpp:265 <VFM_ESINFO> : Entered

        08/17/2011 19:57:07.0282 [TID 0x00019f1c]: VhdManager::claimHyperVGuestId:.\VhdManager.cpp:268 <VFM_ESINFO> : Trying to open E:\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.Z1T3MXMYV02.dominio_1313610938.0.NBU_DATA.xml

        08/17/2011 19:57:07.0282 [TID 0x00019f1c]: VhdManager::claimHyperVGuestId:.\VhdManager.cpp:286 <VFM_ESINFO> : Allocating buffer of filesize 3022 and reading the file

        08/17/2011 19:57:07.0282 [TID 0x00019f1c]: VhdManager::claimHyperVGuestId:.\VhdManager.cpp:298 <VFM_ESINFO> : filesize = 3022 and bytesRead = 3022

        08/17/2011 19:57:07.0282 [TID 0x00019f1c]: VhdManager::claimHyperVGuestId:.\VhdManager.cpp:347 <VFM_ESINFO> : Exited with no claim

        08/17/2011 19:57:07.0282 [TID 0x00019f1c]: VhdCoordinator::vhdMapClaimId:.\VhdCoordinator.cpp:183 <VFM_ESINFO> : Exited

        08/17/2011 19:57:07.0298 [TID 0x00019f1c]: VixInterface::vdInit:.\VixInterface.cpp:157 <VFM_ESINFO> : vixDiskLib config file = [C:\Windows\TEMP\vixFDE2.tmp] 

        08/17/2011 19:57:07.0298 [TID 0x00019f1c]: g_vdInterfaceLogger:.\libvix.cpp:1689 <VFM_ESINFO> : VixDiskLib: config options: libdir 'C:\Program Files\Common Files\VERITAS\VxMS\\Shared\VDDK\', tmpDir 'C:\Windows\TEMP\vmware-SYSTEM'.

        08/17/2011 19:57:07.0454 [TID 0x00019f1c]: g_vdInterfaceLogger:.\libvix.cpp:1689 <VFM_ESINFO> : VixDiskLib: Advanced transport plugin was successfully loaded into vixDiskLib. Accelerated transport modes available.

        08/17/2011 19:57:07.0454 [TID 0x00019f1c]: g_vdInterfaceLogger:.\libvix.cpp:1689 <VFM_ESINFO> : VixDiskLib: Enabling advanced transport modes.

        08/17/2011 19:57:07.0500 [TID 0x00019f1c]: g_vdInterfaceLogger:.\libvix.cpp:1689 <VFM_ESINFO> : VMware VixDiskLib (1.1) Release build-207031

        08/17/2011 19:57:07.0500 [TID 0x00019f1c]: g_vdInterfaceLogger:.\libvix.cpp:1689 <VFM_ESINFO> : Using system libcrypto, version 90805F

        08/17/2011 19:57:08.0982 [TID 0x00019f1c]: vix_map_claim_id:.\libvix.cpp:233 <VFM_ESINFO> : Objid: E:\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.Z1T3MXMYV02.dominio_1313610938.0.NBU_DATA.xml

        08/17/2011 19:57:08.0982 [TID 0x00019f1c]: vix_map_claim_id:.\libvix.cpp:252 <VFM_ESINFO> : Exited

        08/17/2011 19:57:08.0982 [TID 0x00019f1c]: VixCoordinator::vixMapClaimId:.\VixCoordinator.cpp:174 <VFM_ESINFO> : Objid: E:\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.Z1T3MXMYV02.dominio_1313610938.0.NBU_DATA.xml

        08/17/2011 19:57:08.0982 [TID 0x00019f1c]: VixManager::claimId:.\VixManager.cpp:179 <VFM_ESINFO> : Objid: E:\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.Z1T3MXMYV02.dominio_1313610938.0.NBU_DATA.xml

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: vix_map_open_id:.\libvix.cpp:1163 <VFM_ESINFO> : Entered. Flags: 0x80003

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixCoordinator::vixMapOpenId:.\VixCoordinator.cpp:919 <VFM_ESINFO> : Entered. Flags: 0x80003

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixManager::claimId:.\VixManager.cpp:179 <VFM_ESINFO> : Objid: E:\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.Z1T3MXMYV02.dominio_1313610938.0.NBU_DATA.xml

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixManager::openId:.\VixManager.cpp:290 <VFM_ESINFO> : Opening guest

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixManager::openGuest:.\VixManager.cpp:370 <VFM_ESINFO> : Entered. Flags: 0x80003

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixMetaSave::open:.\VixMetaSave.cpp:43 <VFM_ESINFO> : Entered

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixMetaSave::open:.\VixMetaSave.cpp:94 <VFM_ESINFO> : Exited

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixCoordinator::vixMapOpenId:.\VixCoordinator.cpp:935 <VFM_ESINFO> : rflags returned: 0x402307dc

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: vix_map_get_obj_prop:.\libvix.cpp:648 <VFM_ESINFO> : Obj: E:\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.Z1T3MXMYV02.dominio_1313610938.0.NBU_DATA.xml

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixCoordinator::vixMapGetObjProp:.\VixCoordinator.cpp:598 <VFM_ESINFO> : Obj: E:\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.Z1T3MXMYV02.dominio_1313610938.0.NBU_DATA.xml

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixCoordinator::vixMapGetObjProp:.\VixCoordinator.cpp:618 <VFM_ESWARN> : VFM_ENOTSUP on RVP_OBJECT_TYPE_GUEST

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixCoordinator::vixMapGetObjProp:.\VixCoordinator.cpp:636 <VFM_ESERROR> [Sys Error: No error] : Exited with 4

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: vix_map_get_obj_prop:.\libvix.cpp:676 <VFM_ESERROR> [Sys Error: No error] : Error 4

  Output Parameters:

  rflags=0

   [ New Obj ] (0x000000000701AD60)

     vfm_obj_t { 

       obj_name = 0x0000000000000000

       obj_altname = 0x0000000000000000

       obj_orig_name = E:\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.Z1T3MXMYV02.dominio_1313610938.0.NBU_DATA.xml[f9dd0486]

       obj_print_name = E:\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.Z1T3MXMYV02.dominio_1313610938.0.NBU_DATA.xml

       obj_configid = 0x000000000701ADC0

       obj_plugin = 0x0000000003EA04C0

       obj_libpriv = 0x0000000006CC31A0

       obj_pgnpriv = 0x000000000701AD40

     }

End vfm_open_id: result(0)

Begin: vfm_objctl [08/17/11 14:57:08]

  Input Parameters:

  cmd=-103

  arg=0x0000000003D83900

   vfm_obj_t { 

     obj_name = 0x0000000000000000

     obj_altname = 0x0000000000000000

     obj_orig_name = E:\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.Z1T3MXMYV02.dominio_1313610938.0.NBU_DATA.xml[f9dd0486]

     obj_print_name = E:\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.Z1T3MXMYV02.dominio_1313610938.0.NBU_DATA.xml

     obj_configid = 0x000000000701ADC0

     obj_plugin = 0x0000000003EA04C0

     obj_libpriv = 0x0000000006CC31A0

     obj_pgnpriv = 0x000000000701AD40

   }

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: vix_map_objctl:.\libvix.cpp:1102 <VFM_ESINFO> : Obj: E:\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.Z1T3MXMYV02.dominio_1313610938.0.NBU_DATA.xml

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixCoordinator::vixMapObjCtl:.\VixCoordinator.cpp:842 <VFM_ESINFO> : Entered. Cmd: -103

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixCoordinator::vixMapObjCtl:.\VixCoordinator.cpp:844 <VFM_ESINFO> : Obj: E:\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.Z1T3MXMYV02.dominio_1313610938.0.NBU_DATA.xml

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixCoordinator::vixMapObjCtl:.\VixCoordinator.cpp:867 <VFM_ESINFO> : case RVP_OBJECT_TYPE_GUEST

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixMetaSave::logBinaryFile:.\VixMetaSave.cpp:173 <VFM_ESINFO> : Entered

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixMetaSave::logBinaryFile:.\VixMetaSave.cpp:223 <VFM_ESINFO> : Exited

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixGuest::loadVixConfiguration:.\VixGuest.cpp:1196 <VFM_ESINFO> : 

Successfully parsed vix xml file        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixGuest::parseAndLoadDrives:.\VixGuest.cpp:1343 <VFM_ESINFO> : SnapshotName = NBU_SNAPSHOT z1t3mxmyplw05 1313610943

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixGuest::parseAndLoadDrives:.\VixGuest.cpp:1350 <VFM_ESINFO> : SnapshotMoref = 48-snapshot-21

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixGuest::parseAndLoadDrives:.\VixGuest.cpp:1367 <VFM_ESINFO> :  Disk Key = 2000

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixGuest::parseAndLoadDrives:.\VixGuest.cpp:1379 <VFM_ESINFO> :  DiskController = 2000

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixGuest::parseAndLoadDrives:.\VixGuest.cpp:1393 <VFM_ESINFO> :  ChangeId = 

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixGuest::setupVixDiskSnapshotChains:.\VixGuest.cpp:1570 <VFM_ESINFO> : Successfully setup disk snapshot chain

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixGuest::parseAndLoadDrives:.\VixGuest.cpp:1473 <VFM_ESINFO> : Successfully parsed and loaded drives

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixGuest::openVM:.\VixGuest.cpp:707 <VFM_ESINFO> : Successfully loaded Vix configuration

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixGuest::openLeafSnapshotDisks:.\VixGuest.cpp:395 <VFM_ESINFO> : Calling connectToHost(SnapMoRef = 48-snapshot-21, TransportMode = nbd)

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixGuest::connectToHost:.\VixGuest.cpp:892 <VFM_ESINFO> : TransportMode requested: <nbd>

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixGuest::connectToHost:.\VixGuest.cpp:897 <VFM_ESINFO> : Transport Modes available on this host: <file:san:hotadd:nbdssl:nbd>

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixInterface::vdConnect:.\VixInterface.cpp:410 <VFM_ESINFO> : Entered

        08/17/2011 19:57:08.0998 [TID 0x00019f1c]: VixInterface::vdConnect:.\VixInterface.cpp:474 <VFM_ESINFO> : Calling VixDiskLib_ConnectEx()

        08/17/2011 19:57:12.0914 [TID 0x00019f1c]: g_vdInterfaceLogger:.\libvix.cpp:1689 <VFM_ESINFO> : UUID: SMBIOS UUID is reported as '35 38 33 39 31 34 55 53-45 30 35 30 4e 34 36 41'.

        08/17/2011 19:57:13.0179 [TID 0x00019f1c]: VixGuest::connectToHost:.\VixGuest.cpp:948 <VFM_ESINFO> : Setting up VMM interface

        08/17/2011 19:57:13.0179 [TID 0x00019f1c]: VixGuest::connectToHost:.\VixGuest.cpp:982 <VFM_ESINFO> : ChangeTracking is disabled/unsupported

        08/17/2011 19:57:13.0179 [TID 0x00019f1c]: VixGuest::openLeafSnapshotDisks:.\VixGuest.cpp:409 <VFM_ESINFO> : connectToHost() success

        08/17/2011 19:57:13.0179 [TID 0x00019f1c]: VixGuest::openLeafSnapshotDisks:.\VixGuest.cpp:425 <VFM_ESINFO> : Calling vdOpen(Disk = [datastore1] MXMYLA25/MXMYLA25-000002.vmdk, Flags = 0x4)

        08/17/2011 19:57:13.0179 [TID 0x00019f1c]: VixInterface::vdOpen:.\VixInterface.cpp:189 <VFM_ESINFO> : Calling VixDiskLib_Open()

        08/17/2011 19:57:13.0631 [TID 0x00019f1c]: g_vdInterfaceLogger:.\libvix.cpp:1689 <VFM_ESINFO> : VixDiskLib: Trying to open disk [datastore1] MXMYLA25/MXMYLA25-000002.vmdk using mode nbd.

        08/17/2011 19:57:13.0631 [TID 0x00019f1c]: g_vdInterfaceLogger:.\libvix.cpp:1689 <VFM_ESINFO> : NBD_Clientopen: attempting to create connection to ha-nfc://[datastore1] MXMYLA25/MXMYLA25-000002.vmdk@10.112.96.70:902!52 e6 45 67 92 bb f1 a7-83 11 78 fd 89 9a d4 99

        08/17/2011 19:57:13.0631 [TID 0x00019f1c]: g_vdInterfaceLogger:.\libvix.cpp:1689 <VFM_ESINFO> : Started up WSA

        08/17/2011 19:57:13.0741 [TID 0x00019f1c]: g_vdInterfaceLogger:.\libvix.cpp:1693 <VFM_ESWARN> : SSLVerifyCertAgainstSystemStore: Subject mismatch: VWMXMYLA23. vs 10.112.96.70

        08/17/2011 19:57:13.0741 [TID 0x00019f1c]: g_vdInterfaceLogger:.\libvix.cpp:1693 <VFM_ESWARN> : SSLVerifyCertAgainstSystemStore: The remote host certificate has these problems:

* The host name used for the connection does not match the subject name on the host certificate

* The host certificate chain is not complete.

        08/17/2011 19:57:13.0741 [TID 0x00019f1c]: g_vdInterfaceLogger:.\libvix.cpp:1693 <VFM_ESWARN> : SSLVerifyIsEnabled: failed to open the product registry key. Assuming verification is disabled. LastError = 0

        08/17/2011 19:57:13.0741 [TID 0x00019f1c]: g_vdInterfaceLogger:.\libvix.cpp:1693 <VFM_ESWARN> : SSLVerifyCertAgainstSystemStore: Certificate verification is disabled, so connection will proceed despite the error

        08/17/2011 19:57:13.0881 [TID 0x00019f1c]: g_vdInterfaceLogger:.\libvix.cpp:1689 <VFM_ESINFO> : Opening file [datastore1] MXMYLA25/MXMYLA25-000002.vmdk (ha-nfc://[datastore1] MXMYLA25/MXMYLA25-000002.vmdk@10.112.96.70:902!52 e6 45 67 92 bb f1 a7-83 11 78 fd 89 9a d4 99)

        08/17/2011 19:57:13.0928 [TID 0x00019f1c]: g_vdInterfaceLogger:.\libvix.cpp:1693 <VFM_ESWARN> : [NFC ERROR] NfcFssrvr_DiskOpen: received NFC error 11 from server: NfcFssrvrOpen: permission check failed for file [datastore1] MXMYLA25/MXMYLA25-000002.vmdk, access = 1

        08/17/2011 19:57:13.0928 [TID 0x00019f1c]: g_vdInterfaceLogger:.\libvix.cpp:1689 <VFM_ESINFO> : DISKLIB-DSCPTR: : "ha-nfc://[datastore1] MXMYLA25/MXMYLA25-000002.vmdk@10.112.96.70:902!52 e6 45 67 92 bb f1 a7-83 11 78 fd 89 9a d4 99" : Failed to open NBD extent.

        08/17/2011 19:57:13.0928 [TID 0x00019f1c]: g_vdInterfaceLogger:.\libvix.cpp:1689 <VFM_ESINFO> : DISKLIB-LINK  : "ha-nfc://[datastore1] MXMYLA25/MXMYLA25-000002.vmdk@10.112.96.70:902!52 e6 45 67 92 bb f1 a7-83 11 78 fd 89 9a d4 99" : failed to open (NBD_ERR_GENERIC).  

        08/17/2011 19:57:13.0928 [TID 0x00019f1c]: g_vdInterfaceLogger:.\libvix.cpp:1689 <VFM_ESINFO> : DISKLIB-CHAIN : "ha-nfc://[datastore1] MXMYLA25/MXMYLA25-000002.vmdk@10.112.96.70:902!52 e6 45 67 92 bb f1 a7-83 11 78 fd 89 9a d4 99" : failed to open (NBD_ERR_GENERIC).

        08/17/2011 19:57:13.0928 [TID 0x00019f1c]: g_vdInterfaceLogger:.\libvix.cpp:1689 <VFM_ESINFO> : DISKLIB-LIB   : Failed to open 'ha-nfc://[datastore1] MXMYLA25/MXMYLA25-000002.vmdk@10.112.96.70:902!52 e6 45 67 92 bb f1 a7-83 11 78 fd 89 9a d4 99' with flags 0x1e (NBD_ERR_GENERIC).

        08/17/2011 19:57:13.0928 [TID 0x00019f1c]: VixInterface::vdOpen:.\VixInterface.cpp:198 <VFM_ESERROR> [Sys Error: No error] : VixDiskLib_Open() error. Exited

        08/17/2011 19:57:13.0928 [TID 0x00019f1c]: VixGuest::openLeafSnapshotDisks:.\VixGuest.cpp:436 <VFM_ESERROR> [Sys Error: No error] : vdOpen() error = 13. Calling closeLeafSnapshotDisks()

        08/17/2011 19:57:13.0928 [TID 0x00019f1c]: VixGuest::openLeafSnapshotDisks:.\VixGuest.cpp:539 <VFM_ESERROR> [Sys Error: No error] : Exited with failure

        08/17/2011 19:57:13.0928 [TID 0x00019f1c]: VixCoordinator::vixMapObjCtl:.\VixCoordinator.cpp:904 <VFM_ESERROR> [Sys Error: No error] : Exited with 23

        08/17/2011 19:57:13.0928 [TID 0x00019f1c]: vix_map_objctl:.\libvix.cpp:1145 <VFM_ESERROR> [Sys Error: No error] : Error 23

End vfm_objctl: result(23)

Begin: vfm_close [08/17/11 14:57:13]

  Input Parameters:

   vfm_obj_t { 

     obj_name = 0x0000000000000000

     obj_altname = 0x0000000000000000

     obj_orig_name = E:\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.Z1T3MXMYV02.dominio_1313610938.0.NBU_DATA.xml[f9dd0486]

     obj_print_name = E:\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.Z1T3MXMYV02.dominio_1313610938.0.NBU_DATA.xml

     obj_configid = 0x000000000701ADC0

     obj_plugin = 0x0000000003EA04C0

     obj_libpriv = 0x0000000006CC31A0

     obj_pgnpriv = 0x000000000701AD40

   }

        08/17/2011 19:57:13.0928 [TID 0x00019f1c]: vix_map_close:.\libvix.cpp:312 <VFM_ESINFO> : Obj: E:\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.Z1T3MXMYV02.dominio_1313610938.0.NBU_DATA.xml

        08/17/2011 19:57:13.0928 [TID 0x00019f1c]: VixCoordinator::vixMapClose:.\VixCoordinator.cpp:244 <VFM_ESINFO> : Obj: E:\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.Z1T3MXMYV02.dominio_1313610938.0.NBU_DATA.xml

        08/17/2011 19:57:13.0928 [TID 0x00019f1c]: VixCoordinator::vixMapClose:.\VixCoordinator.cpp:265 <VFM_ESINFO> : case RVP_OBJECT_TYPE_GUEST

        08/17/2011 19:57:13.0928 [TID 0x00019f1c]: VixManager::closeGuest:.\VixManager.cpp:57 <VFM_ESINFO> : Obj: E:\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.Z1T3MXMYV02.dominio_1313610938.0.NBU_DATA.xml

        08/17/2011 19:57:13.0928 [TID 0x00019f1c]: VixManager::closeGuest:.\VixManager.cpp:90 <VFM_ESINFO> : Guest has no open file systems hence deleting it

        08/17/2011 19:57:13.0928 [TID 0x00019f1c]: VixGuest::~VixGuest:.\VixGuest.cpp:105 <VFM_ESINFO> : Entered

        08/17/2011 19:57:13.0975 [TID 0x00019f1c]: VixGuest::~VixGuest:.\VixGuest.cpp:214 <VFM_ESINFO> : Cleaned up VM State files

        08/17/2011 19:57:13.0975 [TID 0x00019f1c]: VixGuest::~VixGuest:.\VixGuest.cpp:235 <VFM_ESINFO> : Exited

End vfm_close: result(0)

Begin: vf_free_mapdomain [08/17/11 14:57:13]

  Input Parameters:

   vfm_mapdomain_t { 

     m_node = 0x0000000000000000

   }

End vf_free_mapdomain: result(0)

Begin: vfm_shutdown [08/17/11 14:57:13]

        08/17/2011 19:57:13.0975 [TID 0x00019f1c]: vix_map_fini:.\libvix.cpp:492 <VFM_ESINFO> : Exited with 0

        08/17/2011 19:57:13.0975 [TID 0x00019f1c]: vhd_map_fini:.\libvhd.cpp:448 <VFM_ESINFO> : Entered

        08/17/2011 19:57:13.0975 [TID 0x00019f1c]: VhdCoordinator::vhdMapFini:.\VhdCoordinator.cpp:344 <VFM_ESINFO> : Entered

        08/17/2011 19:57:13.0975 [TID 0x00019f1c]: VhdCoordinator::vhdMapFini:.\VhdCoordinator.cpp:356 <VFM_ESINFO> : Exited

        08/17/2011 19:57:13.0975 [TID 0x00019f1c]: vhd_map_fini:.\libvhd.cpp:463 <VFM_ESINFO> : Exited

End vfm_shutdown: result(0)

[falti_manullang]

i go same problem too..

what is"Virtual machine quiesce" ?

[pikachu]

Best practice is to backup the SQL VMs with the NBU client. Microsoft has a white paper about it for Hyper-V, which is the same thing. Think about it... we do not truncate the logs besides, which means we do not check in what state the DB is in. Also in that case the snapback of the delta data might not always get deleted depending on how busy the system is.

[pikachu]

We flush out everything out of memory to disk.

or to make it simple... let's assume you are at a family function and would like to take a picture of your entire family. You tell them. Everybody look at the camera and smile. You get ready for everybody to smile and take a picture.

If you do not tell them to get ready you just take the picture, while Steve in the background pushes his little sister around, your mom gets your sisters hair ready.... but you still take the picture. You got the picture, but you don't know how presenteable it is.

Makes sense?

How to disable App level quiescing:

http://www.vmware.com/support/developer/vddk/VDDK-1.1.1-Relnotes.html

Windows Server 2008 backup fails due to application level quiescing

Windows Server 2008 virtual machines with the latest VMware Tools installed use application level quiescing for backup on ESX 4.1 hosts, so VDDK 1.1.1 is unable to back them up. This issue has two workarounds. The first is to power off Windows Server 2008 using the vSphere Client, select Settings > Options > General > Configuration Parameters, set disk.EnableUUID to False, save settings, and power on the virtual machine. The second workaround is to create a file in the guest at C:\ProgramData\VMware\VMware Tools\tools.conf with the following contents:

[vmbackup]

I prefer to do it through the VC. I have had times in which case the tools.conf didn't work

[pikachu]

We can't really do anything about the quiescing issue. You might have to go in with perfmon to find out what's constantly reading/writing.

Try to disable app level quiescing.

[mmeeggaann]

Thanks pikachu! I got it, very good explanation.

My insistence about the VM quiesce is because I read the following note of the NBU for VMware  Admin Guide:

" I/O on the virtual machine is quiesced before NetBackup creates the snapshot. 

Without quiescing file activity, data consistency in the snapshot cannot be guaranteed. If not consistent, the backed up data may be of little or no value. 

If this option is disabled, the snapshot is created without quiescing I/O on the virtual machine. In this case, you must perform your own checks for data consistency in the backup data. 

Caution: Symantec does not recommend that you disable quiesce. In most cases, this option should be enabled. "

Disable app level quiescing...

In addition to downtime to apply the change to the VM, what other implications has?

[pikachu]

Disable app level quiescing...

In addition to downtime to apply the change to the VM, what other implications has?

=> Well first of you could try the tools.conf file, which should work, but I have had issues.

what other implications has?

=> Logs will not get truncated so your exchange (or any other service) will just get backed up without checking if it is ready to be backed up.

We released our OWN VSS writer (see nbu admin guide 7.1), which supports exchange. More features are coming in the near future.

[mmeeggaann]

These virtual machines run SQL Server DBs. So, do you know a problem or issue  of disable app quiesce in this case?

[pikachu]

These virtual machines run SQL Server DBs. So, do you know a problem or issue  of disable app quiesce in this case?

Actually I have. Just recently I was working with a customer, who had a VM with SQL installed on it. We had a lot of problem at the end with the backup, because the system was still busy and deleting the snapshot didn't always work.

He installed the NBU client on the machine (best practice for SQL VMs) and started to backup the machine unquiesced.

[mmeeggaann]

Finally we decide to disable  VM quiesce feature in the backup policy and in addition we are backup the SQL databases using the NBU client.

Thanks a lot.

[pikachu]

That's great! Now you have great backups AND you can restore the SQL DB.