VMware backups failing with status code 6/23

[tuan_nguyen1]

Hi everyone,

I have two VMs use the same datastore. I create VMware backup job for each of them with san transport type. VM1 backup succesfully but VM2 is not.

VM1 is a application server, total data is about 50G

VM2 is a file server, total datasize is about 2TB

backup job on VM2 fail once there is an error with "Map disk region" appear on vCenter.

detail logs of VM2:

3/28/2015 9:12:47 PM - Info nbjm(pid=6008) starting backup job (jobid=1851) for client VM2, policy file5, schedule Full  
3/28/2015 9:12:47 PM - estimated 0 Kbytes needed
3/28/2015 9:12:47 PM - Info nbjm(pid=6008) started backup (backupid=VM2_1427551967) job for client VM2, policy file5, schedule Full on storage unit mediaserver-hcart3-robot-tld-0
3/28/2015 9:12:47 PM - started process bpbrm (26331)
3/28/2015 9:12:48 PM - connecting
3/28/2015 9:12:48 PM - connected; connect time: 0:00:00
3/28/2015 9:12:49 PM - mounting PEP041
3/28/2015 9:13:43 PM - mounted; mount time: 0:00:54
3/28/2015 9:13:43 PM - positioning PEP041 to file 1
3/28/2015 9:13:50 PM - positioned PEP041; position time: 0:00:07
3/28/2015 9:13:50 PM - begin writing
3/28/2015 9:20:26 PM - end writing; write time: 0:06:36
3/29/2015 4:11:45 AM - Info bpbrm(pid=26331) VM2 is the host to backup data from     
3/29/2015 4:11:45 AM - Info bpbrm(pid=26331) reading file list for client        
3/29/2015 4:11:45 AM - Info bpbrm(pid=26331) starting bpbkar on client         
3/29/2015 4:11:45 AM - Info bpbkar(pid=26334) Backup started           
3/29/2015 4:11:45 AM - Info bpbrm(pid=26331) bptm pid: 26335          
3/29/2015 4:11:45 AM - Info bptm(pid=26335) start            
3/29/2015 4:11:46 AM - Info bptm(pid=26335) using 65536 data buffer size        
3/29/2015 4:11:46 AM - Info bptm(pid=26335) using 30 data buffers         
3/29/2015 4:11:46 AM - Info bptm(pid=26335) start backup           
3/29/2015 4:11:46 AM - Info bptm(pid=26335) Waiting for mount of media id PEP041 (copy 1) on server mediaserver. 
3/29/2015 4:12:40 AM - Info bptm(pid=26335) media id PEP041 mounted on drive index 2, drivepath /dev/nst2, drivename HP.ULTRIUM6-SCSI.002, copy 1
3/29/2015 4:18:58 AM - Error bpbrm(pid=26331) from client VM2: ERR - Error opening the snapshot disks using given transport mode: Status 23
3/29/2015 4:18:59 AM - Critical bpbrm(pid=26331) from client VM2: FTL - cleanup() failed, status 6    
3/29/2015 4:19:01 AM - Error bptm(pid=26335) media manager terminated by parent process       
3/29/2015 4:19:23 AM - Info bpbkar(pid=0) done. status: 6: the backup failed to back up the requested files 
the backup failed to back up the requested files(6)

VM1:

3/28/2015 9:35:34 PM - Info nbjm(pid=6008) starting backup job (jobid=1854) for client VM1, policy CAS3, schedule Full  
3/28/2015 9:35:34 PM - estimated 0 Kbytes needed
3/28/2015 9:35:34 PM - Info nbjm(pid=6008) started backup (backupid=VM1_1427553334) job for client VM1, policy CAS3, schedule Full on storage unit mediaserver-hcart3-robot-tld-0
3/28/2015 9:35:34 PM - started process bpbrm (22379)
3/28/2015 9:35:35 PM - connecting
3/28/2015 9:35:35 PM - connected; connect time: 0:00:00
3/28/2015 9:35:36 PM - mounting PEP042
3/28/2015 9:36:27 PM - mounted; mount time: 0:00:51
3/28/2015 9:36:27 PM - positioning PEP042 to file 1
3/28/2015 9:36:34 PM - positioned PEP042; position time: 0:00:07
3/28/2015 9:36:34 PM - begin writing
3/28/2015 9:40:59 PM - end writing; write time: 0:04:25
3/29/2015 4:34:32 AM - Info bpbrm(pid=22379) VM1 is the host to backup data from     
3/29/2015 4:34:32 AM - Info bpbrm(pid=22379) reading file list for client        
3/29/2015 4:34:32 AM - Info bpbrm(pid=22379) starting bpbkar on client         
3/29/2015 4:34:32 AM - Info bpbkar(pid=22382) Backup started           
3/29/2015 4:34:32 AM - Info bpbrm(pid=22379) bptm pid: 22383          
3/29/2015 4:34:32 AM - Info bptm(pid=22383) start            
3/29/2015 4:34:33 AM - Info bptm(pid=22383) using 65536 data buffer size        
3/29/2015 4:34:33 AM - Info bptm(pid=22383) using 30 data buffers         
3/29/2015 4:34:33 AM - Info bptm(pid=22383) start backup           
3/29/2015 4:34:33 AM - Info bptm(pid=22383) Waiting for mount of media id PEP042 (copy 1) on server mediaserver. 
3/29/2015 4:35:23 AM - Info bptm(pid=22383) media id PEP042 mounted on drive index 3, drivepath /dev/nst4, drivename HP.ULTRIUM6-SCSI.003, copy 1
3/29/2015 4:35:58 AM - Info bpbkar(pid=22382) INF - Transport Type =  san      
3/29/2015 4:39:36 AM - Info bpbkar(pid=22382) bpbkar waited 27259 times for empty buffer, delayed 51434 times   
3/29/2015 4:39:36 AM - Info bptm(pid=22383) waited for full buffer 4763 times, delayed 6489 times    
3/29/2015 4:39:55 AM - Info bptm(pid=22383) EXITING with status 0 <----------        
3/29/2015 4:39:55 AM - Info bpbrm(pid=22379) validating image for client VM1        
3/29/2015 4:39:56 AM - Info bpbkar(pid=22382) done. status: 0: the requested operation was successfully completed    
the requested operation was successfully completed(0)

Please help me to solve this issue.

Thank you.

Tuan.

[tuan_nguyen1]

ah a little more , VM2 backup job run with NBD mode is successfully, but with san mode is not.

[tuan_nguyen1]

hello

[RiaanBadenhorst]

Hi,

Enable the vxms logs ( http://www.symantec.com/docs/HOWTO70905 ) on level 8 and check what is happening.

[tuan_nguyen1]

Hi, Please view this log

[RiaanBadenhorst · Accepted solution]

Hi,

I think you'll need to pass this to support (Symantec and probably VMware too). Lots of errors with no hits on the web.

   04/02/2015 00:43:55 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:43:55.285+07:00 [2ADC0AE13BC0 error 'Default'] Acquiring disk lease for snapshot-990[HDS-02] HCM-FILESVR5/HCM-FILESVR5_2-000003.vmdk failed with vmodl.fault.SystemError.
   04/02/2015 00:43:55 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:43:55.285+07:00 [2ADC0AE13BC0 error 'Default'] Giving up.
   04/02/2015 00:43:55 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:43:55.286+07:00 [2ADC0AE13BC0 error 'BlockList'] Other error encountered: vmodl.fault.SystemError
   04/02/2015 00:43:55 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:43:55.286+07:00 [2ADC0AE13BC0 error 'Default'] Could not initialize block map.
   04/02/2015 00:43:55 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:43:55.286+07:00 [2ADC0AE13BC0 error 'Default'] San transport error: Unspecified error.
   04/02/2015 00:43:55 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] DISKLIB-LINK  : "san://snapshot-990[HDS-02] HCM-FILESVR5/HCM-FILESVR5_2-000003.vmdk@HCM-SVR-VCENTER.pvep.com.vn:443?Administrator/XXX" : failed to open (Unknown error).  
   04/02/2015 00:43:55 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] DISKLIB-CHAIN : "san://snapshot-990[HDS-02] HCM-FILESVR5/HCM-FILESVR5_2-000003.vmdk@HCM-SVR-VCENTER.pvep.com.vn:443?Administrator/XXX" : failed to open (Unknown error).
   04/02/2015 00:43:55 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] DISKLIB-LIB   : Failed to open 'san://snapshot-990[HDS-02] HCM-FILESVR5/HCM-FILESVR5_2-000003.vmdk@HCM-SVR-VCENTER.pvep.com.vn:443?Administrator/XXX' with flags 0x1e Unknown error (318).
   04/02/2015 00:43:55 : vdOpen:VixInterface.cpp:419 <ERROR> : VixDiskLib_Open() error: 13
   04/02/2015 00:43:55 : openLeafSnapshotDisks:VixGuest.cpp:484 <DEBUG> : vdOpen() error = 13. Calling closeLeafSnapshotDisks()
   04/02/2015 00:43:55 : log:Error.cpp:265 <WARN> : Error: 0x00000017 occured in file VixGuest.cpp, at line 630
   04/02/2015 00:43:55 : log:Error.cpp:265 <WARN> : Error: 0x00000017 occured in file VixGuest.cpp, at line 630
   04/02/2015 00:43:55 : vixMapObjCtl:VixCoordinator.cpp:972 <ERROR> : Returning: 23
   04/02/2015 00:43:55 : vix_map_objctl:libvix.cpp:1258 <ERROR> : Returning: 23

It might also be timing out.

As it does this for a while and then dies.

   04/02/2015 00:37:12 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:37:12.275+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (220481978368 out of 879029649408 bytes mapped).
   04/02/2015 00:37:24 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:37:24.671+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (477896900608 out of 879029649408 bytes mapped).
   04/02/2015 00:37:33 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:37:33.346+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (658385141760 out of 879029649408 bytes mapped).
   04/02/2015 00:37:34 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:37:34.187+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (675417161728 out of 879029649408 bytes mapped).
   04/02/2015 00:37:35 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:37:35.883+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (711530119168 out of 879029649408 bytes mapped).
   04/02/2015 00:37:37 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:37:37.441+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (744419753984 out of 879029649408 bytes mapped).
   04/02/2015 00:37:38 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:37:38.027+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (756281245696 out of 879029649408 bytes mapped).
   04/02/2015 00:37:44 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:37:44.091+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (888367218688 out of 879029649408 bytes mapped).
   04/02/2015 00:38:02 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:38:02.258+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (73021784064 out of 2126001471488 bytes mapped).
   04/02/2015 00:38:10 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:38:10.098+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (173836075008 out of 2126001471488 bytes mapped).
   04/02/2015 00:38:16 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:38:16.589+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (251623636992 out of 2126001471488 bytes mapped).
   04/02/2015 00:38:25 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:38:25.645+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (362531520512 out of 2126001471488 bytes mapped).
   04/02/2015 00:38:35 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:38:35.841+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (486068453376 out of 2126001471488 bytes mapped).
   04/02/2015 00:38:40 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:38:40.732+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (544713211904 out of 2126001471488 bytes mapped).
   04/02/2015 00:38:46 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:38:46.062+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (609730166784 out of 2126001471488 bytes mapped).
   04/02/2015 00:38:52 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:38:52.340+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (686125219840 out of 2126001471488 bytes mapped).
   04/02/2015 00:38:58 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:38:58.328+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (758783148032 out of 2126001471488 bytes mapped).
   04/02/2015 00:39:13 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:39:13.215+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (938157801472 out of 2126001471488 bytes mapped).
   04/02/2015 00:39:25 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:39:25.231+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (1082292961280 out of 2126001471488 bytes mapped).
   04/02/2015 00:39:40 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:39:40.212+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (1263556100096 out of 2126001471488 bytes mapped).
   04/02/2015 00:39:48 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:39:48.977+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (1369228443648 out of 2126001471488 bytes mapped).
   04/02/2015 00:40:10 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:40:10.508+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (1632620249088 out of 2126001471488 bytes mapped).
   04/02/2015 00:40:32 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:40:32.394+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (1901055705088 out of 2126001471488 bytes mapped).
   04/02/2015 00:40:54 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:40:54.789+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (2169491161088 out of 2126001471488 bytes mapped).
   04/02/2015 00:41:03 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:41:03.724+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (73021784064 out of 2126001471488 bytes mapped).
   04/02/2015 00:41:11 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:41:11.588+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (173836075008 out of 2126001471488 bytes mapped).
   04/02/2015 00:41:17 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:41:17.664+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (251623636992 out of 2126001471488 bytes mapped).
   04/02/2015 00:41:26 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:41:26.698+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (362531520512 out of 2126001471488 bytes mapped).
   04/02/2015 00:41:36 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:41:36.533+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (486068453376 out of 2126001471488 bytes mapped).
   04/02/2015 00:41:41 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:41:41.115+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (544713211904 out of 2126001471488 bytes mapped).
   04/02/2015 00:41:46 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:41:46.146+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (609730166784 out of 2126001471488 bytes mapped).
   04/02/2015 00:41:52 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:41:52.131+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (686125219840 out of 2126001471488 bytes mapped).
   04/02/2015 00:41:58 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:41:58.083+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (758783148032 out of 2126001471488 bytes mapped).
   04/02/2015 00:42:12 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:42:12.675+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (938157801472 out of 2126001471488 bytes mapped).
   04/02/2015 00:42:24 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:42:24.408+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (1082292961280 out of 2126001471488 bytes mapped).
   04/02/2015 00:42:39 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:42:39.199+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (1263556100096 out of 2126001471488 bytes mapped).
   04/02/2015 00:42:47 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:42:47.993+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (1369228443648 out of 2126001471488 bytes mapped).
   04/02/2015 00:43:09 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:43:09.851+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (1632620249088 out of 2126001471488 bytes mapped).
   04/02/2015 00:43:31 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:43:31.046+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (1901055705088 out of 2126001471488 bytes mapped).
   04/02/2015 00:43:52 : g_vixInterfaceLogger:libvix.cpp:1825 <DEBUG> : [VFM_ESINFO] 2015-04-02T00:43:52.922+07:00 [2ADC0AE13BC0 verbose 'Default'] Fetching large block map: (2169491161088 out of 2126001471488 bytes mapped).

[tuan_nguyen1]

Thank you for your advice

[Saif_Humaid]

I did find a solution finally after working on this issue for days.

adjust your VMDK size to be either below 2 TB or over 2 TB in size. having a single VMDK that is exactly 2 TB in size will break the SAN transport mechanism in Netbackup and will only alow the backup to only occur over NBD.

In my case, i modified that size of the one VMDK i have from 2 TB to 2.1 TB and that resolved the SAN backup issue i was experiencing.

[sdo]

Hi - can I ask if you were given a TN describing this, and if so would you be able to share a link, please?

[Saif_Humaid]

Hi sdo

I dont have a technical note yet, i still have an active case open with Symantec and i'm letting them know of my findings. I would hope they post a TN and fix the bug that is potentially coded in the VMware SDK.

Another thing to note in my test is that when the VM mahcine is powered off, SAN backups work just fine with the 2 TB VMDK. its only a problem when the VM is powered on and backing up using SAN.

[sdo]

ok - thx Saif.