VMWare Backups Fail with status 11

[pansball]

Hi all.

I encounted an error at 11 when back up vmware.here's some logs.

when I only backup boot disk or data disk,it would be successful.

host name:yzbbxt-db or TESTYZBBXT-DB

time:09/19/16 to 09/21/16

Any guidance would be greatly appreciated,thanks.

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

vxms logs(part):

Begin:vfm_read [19:02:39.0393 : ] 
In: nreq=1
  vfm_obj_t {  orig_name = [HDS_HUS_LUN1_2TB] yzbbxt-db/yzbbxt-db.vmdk  }

  [ I/O Req ]
   vfm_io_req_t { offset = 214748270080 reqlen = 65536 bytes_trans = 0 bytes_req = 0 error = 0  } 

Out:

  [ I/O Req  ]
   vfm_io_req_t { offset = 214748270080 reqlen = 65536 bytes_trans = 65536 bytes_req = 0 error = 0  } 

End:(0)

Begin:vfm_read [19:02:39.0395 : ] 
In: nreq=1
  vfm_obj_t {  orig_name = [HDS_HUS_LUN1_2TB] yzbbxt-db/yzbbxt-db.vmdk  }

  [ I/O Req ]
   vfm_io_req_t { offset = 214748335616 reqlen = 29184 bytes_trans = 0 bytes_req = 0 error = 0  } 

Out:

  [ I/O Req  ]
   vfm_io_req_t { offset = 214748335616 reqlen = 29184 bytes_trans = 29184 bytes_req = 0 error = 0  } 

End:(0)

Begin:vfm_close [19:02:39.0397 : ]    ---close reading
In:  vfm_obj_t {  orig_name = [HDS_HUS_LUN1_2TB] yzbbxt-db/yzbbxt-db.vmdk  }   ---This is the flag for the read completion of this disk

End:(0)   --normal return

Begin:vfm_open_file_name [19:02:39.0431 : ] 
In: filename=<vix>[HDS_HUS_LUN1_2TB] yzbbxt-db/yzbbxt-db_1.vmdk   ---Start reading the next disk
flags=2
context=

Out:
rflags=0
  vfm_obj_t {  orig_name = [HDS_HUS_LUN1_2TB] yzbbxt-db/yzbbxt-db_1.vmdk  }

End:(0)

Begin:vfm_read [19:02:39.0432 : ] 
In: nreq=1
  vfm_obj_t {  orig_name = [HDS_HUS_LUN1_2TB] yzbbxt-db/yzbbxt-db_1.vmdk  }

  [ I/O Req ]
   vfm_io_req_t { offset = 0 reqlen = 35328 bytes_trans = 0 bytes_req = 0 error = 0  }   ---No data to read, return 11 errors, this operation tried three times failed.

bpbkar log(part):

2:42:57.401: [2880.3716] <2> tar_base::V_vTarMsgW: TRV - Called with name = /\\.\VMFILE0, type = 1 (../flashmap.cpp:886)
2:42:57.422: [2880.3716] <2> tar_base::V_vTarMsgW: TRV - Raw partition size=[176, 451892224] (../flashmap.cpp:933)
2:42:57.537: [2880.3716] <2> tar_base::V_vTarMsgW: TRV - write_incr_data size = 261635256320, num_extents = 1384 (../flashmap.cpp:2350)
2:42:57.546: [2880.3716] <2> tar_base::V_vTarMsgW: TRV - Raw partition size =[60, -357748736] (../flashmap.cpp:2925)
2:42:58.727: [2880.3716] <2> tar_base::V_vTarMsgW: INF - File System Name to catalog VMFILE1
2:42:58.779: [2880.3716] <2> tar_base::V_vTarMsgW: TRV - Called with name = /\\.\VMFILE1, type = 2 (../flashmap.cpp:886)
2:42:58.779: [2880.3716] <2> tar_base::V_vTarMsgW: TRV - write for iDataLength = 1024 (../flash_bridge.cpp:465)
2:43:20.525: [2880.3716] <2> tar_base::V_vTarMsgW: TRV - VxMS error - severity 99 (../vxms_bridge.cpp:309)
2:43:20.540: [2880.3716] <2> tar_base::V_vTarMsgW: TRV - VxMS Error message 1 = fiml_read_file vfm_read
message 2 = stat 11 req.io_error 0 (../vxms_bridge.cpp:320)
2:43:20.540: [2880.3716] <2> tar_base::V_vTarMsgW: TRV - Read of VM file read 0 bytes, should have read 5632 bytes, will be issuing retry 1 of 3 (../flashmap.cpp:2411)
2:43:21.540: [2880.3716] <2> tar_base::V_vTarMsgW: TRV - VxMS error - severity 99 (../vxms_bridge.cpp:309)
2:43:21.540: [2880.3716] <2> tar_base::V_vTarMsgW: TRV - VxMS Error message 1 = fiml_read_file vfm_read
message 2 = stat 11 req.io_error 0 (../vxms_bridge.cpp:320)
2:43:21.540: [2880.3716] <2> tar_base::V_vTarMsgW: TRV - Read of VM file read 0 bytes, should have read 5632 bytes, will be issuing retry 2 of 3 (../flashmap.cpp:2411)
2:43:22.540: [2880.3716] <2> tar_base::V_vTarMsgW: TRV - VxMS error - severity 99 (../vxms_bridge.cpp:309)
2:43:22.540: [2880.3716] <2> tar_base::V_vTarMsgW: TRV - VxMS Error message 1 = fiml_read_file vfm_read
message 2 = stat 11 req.io_error 0 (../vxms_bridge.cpp:320)
2:43:22.540: [2880.3716] <2> tar_base::V_vTarMsgW: TRV - Read of VM file read 0 bytes, should have read 5632 bytes, will be issuing retry 3 of 3 (../flashmap.cpp:2411)
2:43:23.540: [2880.3716] <2> tar_base::V_vTarMsgW: TRV - VxMS error - severity 99 (../vxms_bridge.cpp:309)
2:43:23.540: [2880.3716] <2> tar_base::V_vTarMsgW: TRV - VxMS Error message 1 = fiml_read_file vfm_read
message 2 = stat 11 req.io_error 0 (../vxms_bridge.cpp:320)
2:43:23.549: [2880.3716] <2> tar_base::V_vTarMsgW: INF - Read of VM file read 0 bytes, should have read 5632 bytes (../flashmap.cpp:2408)
2:43:31.728: [2880.3716] <2> tar_base::V_vTarMsgW: TRV - VxMS Performance stats: (../vxms_bridge.cpp:906)
2:43:31.728: [2880.3716] <2> tar_base::V_vTarMsgW: TRV - Write Buffer Time: 0, Get Buffer Time: 0 (../vxms_bridge.cpp:909)
2:43:31.728: [2880.3716] <2> tar_base::V_vTarMsgW: TRV - Get Metadata Time: 2222, Write Catalog Time: 7 (../vxms_bridge.cpp:912)
2:43:31.728: [2880.3716] <2> tar_base::V_vTarMsgW: TRV - Create Names Time: 132, Put Tape Time: 11 (../vxms_bridge.cpp:915)
2:43:31.728: [2880.3716] <2> tar_base::V_vTarMsgW: TRV - Build Map Time: 0, Extract Stat Time: 0 (../vxms_bridge.cpp:918)
2:43:31.728: [2880.3716] <2> tar_base::V_vTarMsgW: TRV - Build Image Time: 2376, Next Index Time: 190 (../vxms_bridge.cpp:921)
2:43:31.742: [2880.3716] <2> tar_base::V_vTarMsgW: TRV - Freed bitmap in 0 segments (../flashmap.cpp:1644)
2:43:31.749: [2880.3716] <4> tar_backup::backup_done_state: INF - number of file directives not found: 0
2:43:31.749: [2880.3716] <4> tar_backup::backup_done_state: INF - number of file directives found: 1
2:43:31.770: [2880.2564] <4> tar_base::keepaliveThread: INF - keepalive thread terminating (reason: WAIT_OBJECT_0)
2:43:31.784: [2880.3716] <4> tar_base::stopKeepaliveThread: INF - keepalive thread has exited. (reason: WAIT_OBJECT_0)
2:43:32.039: [2880.3716] <4> send_msg_to_monitor: INF - in send_msg_to_monitor()...
2:43:32.060: [2880.3716] <2> tar_base::V_vTarMsgW: INF - EXIT STATUS 11: system call failed
2:43:32.060: [2880.3716] <4> tar_backup::backup_done_state: INF - Not waiting for server status
2:43:32.140: [2880.3716] <4> dos_backup::tfs_reset: INF - Snapshot deletion start
2:43:32.164: [2880.3716] <4> ov_log::OVLoop: INF - Cycling log file
2:43:32.164: [2880.3716] <4> ov_log::OVClose: INF - Closing log file: C:\Program Files\Veritas\NetBackup\logs\BPBKAR\091916.LOG

bpbrm logs(part):

00:38:23.903 [1484.3560] <2> bpbrm main: end write catalog
00:38:23.903 [1484.3560] <2> bpbrm main: ADDED FILES TO DB FOR TESTYZBBXT-DB_1474300397 37 /boot
00:38:23.903 [1484.3560] <2> set_job_details: Tfile (17720): LOG 1474303103 4 bpbkar32 2880 606297 entries sent to bpdbm

00:38:23.903 [1484.3560] <2> send_job_file: job ID 17720, ftype = 3 msg len = 60, msg = LOG 1474303103 4 bpbkar32 2880 606297 entries sent to bpdbm

00:38:23.903 [1484.3560] <2> bpbrm main: from client TESTYZBBXT-DB: INF - Transport Type = nbd
00:38:23.903 [1484.3560] <2> set_job_details: Tfile (17720): LOG 1474303103 4 bpbkar32 2880 INF - Transport Type = nbd

00:38:23.903 [1484.3560] <2> send_job_file: job ID 17720, ftype = 3 msg len = 58, msg = LOG 1474303103 4 bpbkar32 2880 INF - Transport Type = nbd

00:38:23.903 [1484.3560] <2> bpbrm main: from client TESTYZBBXT-DB: INF - File System Name to catalog VIRTUAL_FILE
00:38:35.448 [1484.3560] <2> bpbrm main: from client TESTYZBBXT-DB: INF - File System Name to catalog VIRTUAL_FILE
00:38:35.465 [1484.3560] <2> bpbrm main: from client TESTYZBBXT-DB: INF - File System Name to catalog VMFILE0
02:42:58.864 [1484.3560] <2> bpbrm main: from client TESTYZBBXT-DB: INF - File System Name to catalog VMFILE1
02:43:32.298 [1484.3560] <2> set_job_details: Tfile (17720): LOG 1474310612 4 bpbkar32 2880 bpbkar waited 224 times for empty buffer, delayed 7600 times.

02:43:32.298 [1484.3560] <2> send_job_file: job ID 17720, ftype = 3 msg len = 93, msg = LOG 1474310612 4 bpbkar32 2880 bpbkar waited 224 times for empty buffer, delayed 7600 times.

02:43:32.313 [1484.3560] <2> bpbrm main: client TESTYZBBXT-DB EXIT STATUS = 11: system call failed
02:43:32.316 [1484.3560] <2> bpbrm kill_child_process_Ex: start
02:43:42.625 [1484.3560] <2> bpbrm wait_for_child: start
02:43:42.625 [1484.3560] <2> bpbrm wait_for_child: child exit_status = 82
02:43:42.634 [1484.3560] <2> inform_client_of_status: INF - Server status = 11
02:43:42.722 [1484.3560] <2> put_string: cannot write data to network: 远程主机强迫关闭了一个现有的连接。
02:43:42.835 [1484.3560] <16> inform_client_of_status: could not send server status message
02:43:42.847 [1484.3560] <2> set_job_details: Tfile (17720): LOG 1474310622 16 bpbrm 1484 could not send server status message

02:43:42.847 [1484.3560] <2> send_job_file: job ID 17720, ftype = 3 msg len = 66, msg = LOG 1474310622 16 bpbrm 1484 could not send server status message

02:43:42.859 [1484.3560] <2> ConnectionCache::connectAndCache: Acquiring new connection for host iap-zq-bak01, query type 1

bptm logs(part):

13:26:45.305 [3404.3560] <4> write_backup: successfully wrote backup id TESTYZBBXT-DB_1474253996, copy 1, fragment 1, 209715230 Kbytes at 24157.991 Kbytes/sec
13:26:47.332 [3404.3560] <2> io_close: closing C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_IBM.ULTRIUM-TD3.001, from bptm.c.16433
13:26:47.332 [3404.3560] <2> drivename_write: Called with mode 1
13:26:47.335 [3404.3560] <2> drivename_unlock: unlocked
13:26:47.344 [3404.3560] <2> drivename_checklock: Called
13:26:47.344 [3404.3560] <2> drivename_lock: lock established
13:26:47.344 [3404.3560] <2> drivename_unlock: unlocked
13:26:47.344 [3404.3560] <2> drivename_close: Called for file IBM.ULTRIUM-TD3.001
13:26:47.348 [3404.3560] <2> send_MDS_msg: MEDIA_DONE 0 -1474250245 0 LH0063 4000414 0 {5DFA8085-67C3-4195-B08A-C9D108AFBB49}
13:26:47.354 [3404.3560] <2> JobInst::sendIrmMsg: starting
13:26:47.391 [3404.3560] <2> packageBptmResourceDoneMsg: msg (MEDIA_DONE 0 -1474250245 0 LH0063 4000414 0 {5DFA8085-67C3-4195-B08A-C9D108AFBB49})
13:26:47.391 [3404.3560] <2> packageBptmResourceDoneMsg: keyword MEDIA_DONE version 0 jobid -1474250245 copyNum 0 mediaId LH0063 mediaKey 4000414 unloadDelay 0 allocId {5DFA8085-67C3-4195-B08A-C9D108AFBB49}
13:26:47.406 [3404.3560] <2> packageBptmResourceDoneMsg: returns 0
13:26:48.320 [3404.3560] <2> JobInst::sendIrmMsg: returning
13:26:48.320 [3404.3560] <2> mm_terminate: EXITING with status 82
13:26:51.320 [3404.3560] <2> cleanup: Detached from BPBRM shared memory

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

and,here's some logs from vmware

hostd、vpxa、vmware:

vpxa(part):

2016-09-14T06:46:26.181Z [FFB03B70 verbose 'vpxavpxaMoVm' opID=SWI-9e91f12e] [VpxaMoVm::CheckMoVm] did not find a VM with ID 59 in the vmList
2016-09-14T06:46:26.181Z [FFB03B70 verbose 'vpxavpxaAlarm' opID=SWI-9e91f12e] [VpxaAlarm] VM with vmid = 59 not found
2016-09-14T06:46:36.183Z [FFB03B70 verbose 'vpxavpxaMoVm' opID=SWI-9e91f12e] [VpxaMoVm::CheckMoVm] did not find a VM with ID 59 in the vmList
2016-09-14T06:46:36.183Z [FFB03B70 verbose 'vpxavpxaAlarm' opID=SWI-9e91f12e] [VpxaAlarm] VM with vmid = 59 not found

hostd(part):

2016-09-14T03:34:27.003Z [2A681B70 verbose 'Default' opID=69c6fd79-a9 user=vpxuser] AdapterServer: target='vim.VirtualMachine:37', method='queryChangedDiskAreas'
2016-09-14T03:34:27.017Z [2A681B70 error 'Vmsvc.vm:/vmfs/volumes/5036aacb-761921f0-4ceb-3440b5b0b762/yzbbxt-db/yzbbxt-db.vmx' opID=69c6fd79-a9 user=vpxuser] Cannot compute changes for disk /vmfs/volumes/5036aacb-761921f0-4ceb-3440b5b0b762/yzbbxt-db/yzbbxt-db_1.vmdk: Unknown change epoch.
2016-09-14T03:34:27.017Z [2A681B70 info 'Default' opID=69c6fd79-a9 user=vpxuser] AdapterServer caught exception: vim.fault.FileFault
2016-09-14T03:34:27.017Z [2A681B70 info 'Solo.Vmomi' opID=69c6fd79-a9 user=vpxuser] Activation [N5Vmomi10ActivationE:0x28694ca0] : Invoke done [queryChangedDiskAreas] on [vim.VirtualMachine:37]

[Michael_G_Ander]

As this VM seems to contain a database, make sure that database is quiesced as a part of the snapshot.

Trying to do a snapshot of an unquiesced database can very easy give status 11.

If the VM has RDM's you cannot use vmware backup for those disks as vmware cannot make snapshot of them.

Can your vmware administrator do a snapshot with quiesce filesystem of this VM ?