Question

RHEV VM backup Error 91:488 Unknown VMInfo error [0]

  • 28 February 2024
  • 5 replies
  • 171 views

Badge +4

Hello dears 

 

im facing a weird issue regarding redhat virtualization backup

 client configuration is ok, proxy VM is located on the RHEV 

backup was performing ok but, suddenly  an issue while backing up the VMs most of the VMs failed to back up with the below error 

Unknown VMInfo error [0] reported  from VMinfo for [VM name ]  

i have checked the vsbkp log but couldn’t find a clear error 

cvfwd log does not have any errors. 

CS version 11.32.23

assistance is appreciated, thanks 


5 replies

Userlevel 2
Badge +4

Hi @Mansour_Nour 

Thank you for reaching out.

Could you please suggest if you are facing an issue with a single VM or multiple?

Is it a new configuration or were the backups running fine. 

 

Also, if possible, could you please paste the vsbkp logs here to check and guide to further. 

 

 

Badge +4

Hi @nishas 

its a 3 month configuration and backup was running fine then the issue poped up.

most of the vms are failing.

 

vsbkp log

 

4000  293c  02/27 18:29:27 104295 VSBkpWorker::CheckAndConvertJobToFull() - Previous backup job for VM [PDC1-SHYPLN-APP01] Guid [4b754a1b-70db-4fe9-9648-2d5cbd538e24] was [Streaming]
4000  293c  02/27 18:29:27 104295 VSBkpWorker::ProcessVM() - Metadata for VM [PDC1-SHYPLN-APP01] components received from previous successful backup job
4000  293c  02/27 18:29:27 104295 VSBkpWorker::ProcessVM() - IndexName [6a09845d-d5dd-4835-80b7-ffb319858997] Extent Size [512] ChangeId []
4000  293c  02/27 18:29:27 104295 VSBkpWorker::ProcessVM() - IndexName [d0235559-e5a2-4ecd-964f-a284fae32e00] Extent Size [512] ChangeId []
4000  293c  02/27 18:29:27 104295 VSBkpWorker::ProcessVM() - IndexName [PDC1-SHYPLN-APP01.ovf] Extent Size [20027] ChangeId []
4000  293c  02/27 18:29:27 104295 VSBkpWorker::ProcessVM() - IndexName [VMConfig.cvf] Extent Size [921] ChangeId []
4000  293c  02/27 18:29:27 104295 VSBkpWorker::SendBLRPreSnapVM() - There are no pairs in the DB with subclient id [0], VM Guid[4B754A1B-70DB-4FE9-9648-2D5CBD538E24]
4000  37e8  02/27 18:29:28 104295 CRhevInfo::_MountVM_rcb() - Mounting VM:[PDC1-SEBS-APPUI02] with GUID:[b904f74e-1a5d-4946-8876-52aae0ff9ff6]
4000  293c  02/27 18:29:30 104295 CRhevInfo::_MountVM_rcb() - Mounting VM:[PDC1-SHYPLN-APP01] with GUID:[4b754a1b-70db-4fe9-9648-2d5cbd538e24]
4000  37e8  02/27 18:29:46 104295 CRhevInfo::_MountVM_rcb() - Creating snapshot with description [_GX_BACKUP_PDC1-SEBS-APPUI02_104295_4000_pdc1-ppcmv-vsa2]
4000  293c  02/27 18:29:46 104295 CRhevInfo::_MountVM_rcb() - Creating snapshot with description [_GX_BACKUP_PDC1-SHYPLN-APP01_104295_4000_pdc1-ppcmv-vsa2]
4000  3794  02/27 18:29:46 104295 VSBkpController::MonitorProgress() - [4] VMs are being processed
4000  2be8  02/27 18:29:46 104295 VSBkpCoordinator::OnIdle_Running() - Waiting for [20] VMs to be processed.  [PDC1-SODQ-APP01, PDC1-SHYPFDME-APP01, PDC1-SHYPLN-SUPP01...]
4000  2be8  02/27 18:29:46 104295 VSBkpCoordinator::OnIdle_Running() - [15] have not been dispatched
4000  2be8  02/27 18:29:46 104295 VSBkpCoordinator::DumpStreamInfo() - StreamId =   5, RCID = 187851, ReservationId = 180891, MediaAgent = [PDC1PP-COM-MA1], Agent = [pdc1-ppcmv-vsa2]  [Assigned]
4000  2be8  02/27 18:29:46 104295 VSBkpCoordinator::DumpStreamInfo() - StreamId =   7, RCID = 187858, ReservationId = 180896, MediaAgent = [PDC1PP-COM-MA1], Agent = [pdc1-ppcmv-vsa01]  [Assigned]
4000  2be8  02/27 18:29:46 104295 VSBkpCoordinator::DumpStreamInfo() - StreamId =   8, RCID = 187859, ReservationId = 180897, MediaAgent = [PDC1PP-COM-MA1], Agent = [pdc1-ppcmv-vsa2]  [Assigned]
4000  2be8  02/27 18:29:46 104295 VSBkpCoordinator::DumpStreamInfo() - StreamId =   9, RCID = 187860, ReservationId = 180898, MediaAgent = [PDC1PP-COM-MA1], Agent = [pdc1-ppcmv-vsa2]  [Assigned]
4000  2be8  02/27 18:29:46 104295 VSBkpCoordinator::DumpStreamInfo() - StreamId =  10, RCID = 187861, ReservationId = 180899, MediaAgent = [PDC1PP-COM-MA1], Agent = [pdc1-ppcmv-vsa2]  [Assigned]
4000  2be8  02/27 18:29:46 104295 VSBkpCoordinator::OnIdle_Running() - Agent [pdc1-ppcmv-vsa01] is [Running]  1 VMs   1 Streams
4000  2be8  02/27 18:29:46 104295 VSBkpCoordinator::OnIdle_Running() - Agent [pdc1-ppcmv-vsa2] is [Running]  4 VMs   4 Streams
4000  37e8  02/27 18:29:52 104295 RhevSDKWrapper::CVRhevOperations::pollVMSnapshotStatus() - Correlation Id [104295_4000_1709047787] does not match with job [Creating VM Snapshot _GX_BACKUP_PDC1-SEBS-APPUI02_104295_4000_pdc1-ppcmv-vsa2 for VM PDC1-SEBS-APPUI02][171772f1-0a53-4bfb-80b0-bdd164dfb75e]
4000  293c  02/27 18:29:53 104295 RhevSDKWrapper::CVRhevOperations::pollVMSnapshotStatus() - Correlation Id [104295_4000_1709047789] does not match with job [Creating VM Snapshot _GX_BACKUP_PDC1-SHYPLN-APP01_104295_4000_pdc1-ppcmv-vsa2 for VM PDC1-SHYPLN-APP01][853131dc-33a1-444f-ada3-3e77bbf73b78]
4000  37e8  02/27 18:30:08 104295 RhevSDKWrapper::CVRhevOperations::checkSnapshotStatusCallBack() - snapshot status [ok] ready
4000  293c  02/27 18:30:09 104295 RhevSDKWrapper::CVRhevOperations::checkSnapshotStatusCallBack() - snapshot status [ok] ready
4000  293c  02/27 18:30:11 104295 RhevSDKWrapper::CVRhevOperations::createVMSnapshot() - VM Snapshot created successfully. ID[332c7d70-e708-4a21-a9f0-08cbe432531e] Desc[_GX_BACKUP_PDC1-SHYPLN-APP01_104295_4000_pdc1-ppcmv-vsa2]
4000  293c  02/27 18:30:11 104295 RhevSDKWrapper::CVRhevSDKWrapper::createVMSnapshot() - CreateVM Snapshot successful
4000  293c  02/27 18:30:11 104295 CRhevInfo::_MountVM_rcb() - Snapshot [332c7d70-e708-4a21-a9f0-08cbe432531e] created for VM [PDC1-SHYPLN-APP01] successfully
4000  293c  02/27 18:30:11 104295 VSBkpWorker::SaveCleanupString() - Saving Cleanup string [VSIDA -j 104295 -a 2:322 -vmHost "mod-dc01-prod-rhv-mgmt-01.mod.mil" -vmName "PDC1-SHYPLN-APP01" -vmGuid "4b754a1b-70db-4fe9-9648-2d5cbd538e24" -vmCleanup "332c7d70-e708-4a21-a9f0-08cbe432531e" ] with JobManager
4000  293c  02/27 18:30:11 104295 VMCleaner::LookupEntity() - Looking up [C:\Program Files\Commvault\ContentStore\iDataAgent\JobResults\CV_JobResults\14D8A66B-9B0C-4C7B-BC4D-762A7F6F7E33\BACKUP\4000-vsbkp.exe\VM\4b754a1b-70db-4fe9-9648-2d5cbd538e24]...not found!
4000  293c  02/27 18:30:11 104295 CRhevInfo::SaveVMConfigFile() - Wrote vm config file successfully to [C:\Program Files\Commvault\ContentStore\iDataAgent\JobResults\CV_JobResults\iDataAgent\VirtualServerAgent\2\322\(4b754a1b-70db-4fe9-9648-2d5cbd538e24)\PDC1-SHYPLN-APP01.ovf]
4000  293c  02/27 18:30:11 104295 CRhevInfo::_MountVM_rcb() - VM config file saved successfully
4000  37e8  02/27 18:30:11 104295 RhevSDKWrapper::CVRhevOperations::createVMSnapshot() - VM Snapshot created successfully. ID[4d42bcdd-e40b-4e9f-bbe9-bb25b0c52182] Desc[_GX_BACKUP_PDC1-SEBS-APPUI02_104295_4000_pdc1-ppcmv-vsa2]
4000  37e8  02/27 18:30:11 104295 RhevSDKWrapper::CVRhevSDKWrapper::createVMSnapshot() - CreateVM Snapshot successful
4000  37e8  02/27 18:30:11 104295 CRhevInfo::_MountVM_rcb() - Snapshot [4d42bcdd-e40b-4e9f-bbe9-bb25b0c52182] created for VM [PDC1-SEBS-APPUI02] successfully
4000  37e8  02/27 18:30:11 104295 VSBkpWorker::SaveCleanupString() - Saving Cleanup string [VSIDA -j 104295 -a 2:322 -vmHost "mod-dc01-prod-rhv-mgmt-01.mod.mil" -vmName "PDC1-SEBS-APPUI02" -vmGuid "b904f74e-1a5d-4946-8876-52aae0ff9ff6" -vmCleanup "4d42bcdd-e40b-4e9f-bbe9-bb25b0c52182" ] with JobManager
4000  37e8  02/27 18:30:11 104295 VMCleaner::LookupEntity() - Looking up [C:\Program Files\Commvault\ContentStore\iDataAgent\JobResults\CV_JobResults\14D8A66B-9B0C-4C7B-BC4D-762A7F6F7E33\BACKUP\4000-vsbkp.exe\VM\b904f74e-1a5d-4946-8876-52aae0ff9ff6]...not found!
4000  37e8  02/27 18:30:11 104295 CRhevInfo::SaveVMConfigFile() - Wrote vm config file successfully to [C:\Program Files\Commvault\ContentStore\iDataAgent\JobResults\CV_JobResults\iDataAgent\VirtualServerAgent\2\322\(b904f74e-1a5d-4946-8876-52aae0ff9ff6)\PDC1-SEBS-APPUI02.ovf]
4000  37e8  02/27 18:30:11 104295 CRhevInfo::_MountVM_rcb() - VM config file saved successfully
4000  3794  02/27 18:30:16 104295 VSBkpController::MonitorProgress() - [4] VMs are being processed
4000  293c  02/27 18:30:17 104295 RhevSDKWrapper::CVRhevOperations::attachDisk() - Attached disk [6a09845d-d5dd-4835-80b7-ffb319858997] snapshotid [332c7d70-e708-4a21-a9f0-08cbe432531e] to VMid [14D8A66B-9B0C-4C7B-BC4D-762A7F6F7E33]
4000  293c  02/27 18:30:17 104295 CRhevInfo::AttachAndActivateDisk() - Disk [6a09845d-d5dd-4835-80b7-ffb319858997] attached successfully
4000  293c  02/27 18:30:17 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  293c  02/27 18:30:22 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  293c  02/27 18:30:27 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  293c  02/27 18:30:32 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  3794  02/27 18:30:36 104295 VSBkpController::MonitorIndexing() - Closing idle Indexing connection.  Reused [3] times, Idle for [70] seconds
4000  293c  02/27 18:30:37 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  293c  02/27 18:30:42 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  3794  02/27 18:30:46 104295 VSBkpController::MonitorProgress() - [4] VMs are being processed
4000  293c  02/27 18:30:47 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  293c  02/27 18:30:52 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  293c  02/27 18:30:57 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  293c  02/27 18:31:02 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  293c  02/27 18:31:07 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  293c  02/27 18:31:12 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  3794  02/27 18:31:16 104295 VSBkpController::MonitorProgress() - [4] VMs are being processed
4000  293c  02/27 18:31:17 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  293c  02/27 18:31:22 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  293c  02/27 18:31:27 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  293c  02/27 18:31:32 104295 CDiskMapperWindows::PostAttachDisk() - Failed to find the newly added disk
4000  293c  02/27 18:31:32 104295 CRhevInfo::ConnectDiskToProxy() - attached: 1, registered: 1, postAttachRet: 0
4000  293c  02/27 18:31:32 104295 CRhevInfo::ConnectDiskToProxy() - DiskMapper PostAttach failed for disk [] [6a09845d-d5dd-4835-80b7-ffb319858997]
4000  37e8  02/27 18:31:38 104295 RhevSDKWrapper::CVRhevOperations::attachDisk() - Attached disk [080bccbe-733b-4d24-acf7-018b04f8ed95] snapshotid [4d42bcdd-e40b-4e9f-bbe9-bb25b0c52182] to VMid [14D8A66B-9B0C-4C7B-BC4D-762A7F6F7E33]
4000  37e8  02/27 18:31:38 104295 CRhevInfo::AttachAndActivateDisk() - Disk [080bccbe-733b-4d24-acf7-018b04f8ed95] attached successfully
4000  293c  02/27 18:31:38 104295 CRhevInfo::DetatchAndDeactivateDisk() - Disk [6a09845d-d5dd-4835-80b7-ffb319858997] deactivated successfully
4000  37e8  02/27 18:31:38 104295 CRhevInfo::ConnectDiskToProxy() - attached: 1, registered: 1, postAttachRet: 1
4000  37e8  02/27 18:31:38 104295 CRhevInfo::ConnectDiskToProxy() - Disk [080bccbe-733b-4d24-acf7-018b04f8ed95] is attached at [\\?\scsi#disk&ven_qemu&prod_qemu_harddisk#5&1a1a9dad&0&000002#{53f56307-b6bf-11d0-94f2-00a0c91efb8b}]
4000  293c  02/27 18:31:43 104295 RhevSDKWrapper::CVRhevOperations::detachDisk() - Detached disk [6a09845d-d5dd-4835-80b7-ffb319858997] from VM [14D8A66B-9B0C-4C7B-BC4D-762A7F6F7E33]
4000  293c  02/27 18:31:43 104295 RhevSDKWrapper::CVRhevSDKWrapper::detachDisk() - Disk [6a09845d-d5dd-4835-80b7-ffb319858997] is detached successfully
4000  293c  02/27 18:31:43 104295 CRhevInfo::DetatchAndDeactivateDisk() - Disk [6a09845d-d5dd-4835-80b7-ffb319858997] detached successfully
4000  3794  02/27 18:31:46 104295 VSBkpController::MonitorProgress() - [4] VMs are being processed
4000  37e8  02/27 18:31:49 104295 RhevSDKWrapper::CVRhevOperations::attachDisk() - Attached disk [06aade11-7114-4e47-826c-1b28e537f031] snapshotid [4d42bcdd-e40b-4e9f-bbe9-bb25b0c52182] to VMid [14D8A66B-9B0C-4C7B-BC4D-762A7F6F7E33]
4000  37e8  02/27 18:31:49 104295 CRhevInfo::AttachAndActivateDisk() - Disk [06aade11-7114-4e47-826c-1b28e537f031] attached successfully
4000  37e8  02/27 18:31:49 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  37e8  02/27 18:31:54 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  37e8  02/27 18:31:59 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  37e8  02/27 18:32:04 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  37e8  02/27 18:32:09 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  37e8  02/27 18:32:14 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  3794  02/27 18:32:17 104295 VSBkpController::MonitorProgress() - [4] VMs are being processed
4000  37e8  02/27 18:32:19 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  37e8  02/27 18:32:24 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  37e8  02/27 18:32:29 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  37e8  02/27 18:32:34 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  37e8  02/27 18:32:39 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  37e8  02/27 18:32:44 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  3794  02/27 18:32:47 104295 VSBkpController::MonitorProgress() - [4] VMs are being processed
4000  37e8  02/27 18:32:49 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  37e8  02/27 18:32:54 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  37e8  02/27 18:32:59 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  37e8  02/27 18:33:04 104295 CDiskMapperWindows::PostAttachDisk() - Failed to find the newly added disk
4000  37e8  02/27 18:33:04 104295 CRhevInfo::ConnectDiskToProxy() - attached: 1, registered: 1, postAttachRet: 0
4000  37e8  02/27 18:33:04 104295 CRhevInfo::ConnectDiskToProxy() - DiskMapper PostAttach failed for disk [] [06aade11-7114-4e47-826c-1b28e537f031]
4000  293c  02/27 18:33:10 104295 RhevSDKWrapper::CVRhevOperations::attachDisk() - Attached disk [d0235559-e5a2-4ecd-964f-a284fae32e00] snapshotid [332c7d70-e708-4a21-a9f0-08cbe432531e] to VMid [14D8A66B-9B0C-4C7B-BC4D-762A7F6F7E33]
4000  293c  02/27 18:33:10 104295 CRhevInfo::AttachAndActivateDisk() - Disk [d0235559-e5a2-4ecd-964f-a284fae32e00] attached successfully
4000  293c  02/27 18:33:10 104295 CRhevInfo::ConnectDiskToProxy() - attached: 1, registered: 1, postAttachRet: 1
4000  293c  02/27 18:33:10 104295 CRhevInfo::ConnectDiskToProxy() - Disk [d0235559-e5a2-4ecd-964f-a284fae32e00] is attached at [\\?\scsi#disk&ven_qemu&prod_qemu_harddisk#5&1a1a9dad&0&000007#{53f56307-b6bf-11d0-94f2-00a0c91efb8b}]
4000  293c  02/27 18:33:10 104295 CRhevInfo::_MountVM_rcb() - Attached 1 disks for VM [PDC1-SHYPLN-APP01]
4000  37e8  02/27 18:33:10 104295 CRhevInfo::DetatchAndDeactivateDisk() - Disk [06aade11-7114-4e47-826c-1b28e537f031] deactivated successfully
4000  293c  02/27 18:33:11 104295 CRhevInfo::_MountVM_rcb() - Failed to connect disk [6a09845d-d5dd-4835-80b7-ffb319858997] to proxy
4000  293c  02/27 18:33:11 104295 CRhevInfo::UnmountVM() - Disk Count to disconnect from Proxy: 1
4000  37e8  02/27 18:33:16 104295 RhevSDKWrapper::CVRhevOperations::detachDisk() - Detached disk [06aade11-7114-4e47-826c-1b28e537f031] from VM [14D8A66B-9B0C-4C7B-BC4D-762A7F6F7E33]
4000  37e8  02/27 18:33:16 104295 RhevSDKWrapper::CVRhevSDKWrapper::detachDisk() - Disk [06aade11-7114-4e47-826c-1b28e537f031] is detached successfully
4000  37e8  02/27 18:33:16 104295 CRhevInfo::DetatchAndDeactivateDisk() - Disk [06aade11-7114-4e47-826c-1b28e537f031] detached successfully
4000  293c  02/27 18:33:16 104295 CRhevInfo::DetatchAndDeactivateDisk() - Disk [d0235559-e5a2-4ecd-964f-a284fae32e00] deactivated successfully
4000  37e8  02/27 18:33:16 104295 CRhevInfo::_MountVM_rcb() - Attached 1 disks for VM [PDC1-SEBS-APPUI02]
4000  37e8  02/27 18:33:16 104295 CRhevInfo::_MountVM_rcb() - Failed to connect disk [06aade11-7114-4e47-826c-1b28e537f031] to proxy
4000  37e8  02/27 18:33:16 104295 CRhevInfo::UnmountVM() - Disk Count to disconnect from Proxy: 1
4000  3794  02/27 18:33:17 104295 VSBkpController::MonitorProgress() - [4] VMs are being processed
4000  293c  02/27 18:33:21 104295 RhevSDKWrapper::CVRhevOperations::detachDisk() - Detached disk [d0235559-e5a2-4ecd-964f-a284fae32e00] from VM [14D8A66B-9B0C-4C7B-BC4D-762A7F6F7E33]
4000  293c  02/27 18:33:21 104295 RhevSDKWrapper::CVRhevSDKWrapper::detachDisk() - Disk [d0235559-e5a2-4ecd-964f-a284fae32e00] is detached successfully
4000  293c  02/27 18:33:21 104295 CRhevInfo::DetatchAndDeactivateDisk() - Disk [d0235559-e5a2-4ecd-964f-a284fae32e00] detached successfully
4000  293c  02/27 18:33:21 104295 CRhevInfo::DisconnectDiskFromProxy() - Disk [\\?\scsi#disk&ven_qemu&prod_qemu_harddisk#5&1a1a9dad&0&000007#{53f56307-b6bf-11d0-94f2-00a0c91efb8b}] detached successfully
4000  293c  02/27 18:33:21 104295 CDiskMapperWindows::_DeviceNodeCleanup() - Successfully removed [1] orphaned device entries
4000  293c  02/27 18:33:21 104295 CRhevInfo::DeleteVMSnapshot() - Snapshot [332c7d70-e708-4a21-a9f0-08cbe432531e] of VM [4b754a1b-70db-4fe9-9648-2d5cbd538e24] is going to be deleted...
4000  37e8  02/27 18:33:21 104295 CRhevInfo::DetatchAndDeactivateDisk() - Disk [080bccbe-733b-4d24-acf7-018b04f8ed95] deactivated successfully
4000  37e8  02/27 18:33:26 104295 RhevSDKWrapper::CVRhevOperations::detachDisk() - Detached disk [080bccbe-733b-4d24-acf7-018b04f8ed95] from VM [14D8A66B-9B0C-4C7B-BC4D-762A7F6F7E33]
4000  37e8  02/27 18:33:26 104295 RhevSDKWrapper::CVRhevSDKWrapper::detachDisk() - Disk [080bccbe-733b-4d24-acf7-018b04f8ed95] is detached successfully
4000  37e8  02/27 18:33:26 104295 CRhevInfo::DetatchAndDeactivateDisk() - Disk [080bccbe-733b-4d24-acf7-018b04f8ed95] detached successfully
4000  37e8  02/27 18:33:26 104295 CRhevInfo::DisconnectDiskFromProxy() - Disk [\\?\scsi#disk&ven_qemu&prod_qemu_harddisk#5&1a1a9dad&0&000002#{53f56307-b6bf-11d0-94f2-00a0c91efb8b}] detached successfully
4000  37e8  02/27 18:33:26 104295 CDiskMapperWindows::_DeviceNodeCleanup() - Successfully removed [1] orphaned device entries
4000  37e8  02/27 18:33:26 104295 CRhevInfo::DeleteVMSnapshot() - Snapshot [4d42bcdd-e40b-4e9f-bbe9-bb25b0c52182] of VM [b904f74e-1a5d-4946-8876-52aae0ff9ff6] is going to be deleted...
4000  3794  02/27 18:33:47 104295 VSBkpController::MonitorProgress() - [4] VMs are being processed
4000  293c  02/27 18:33:54 104295 RhevSDKWrapper::CVRhevOperations::pollForRhevJobCompletion() - Job Complete [2db078f5-ff41-4891-a946-d57124017367] [Removing Snapshot _GX_BACKUP_PDC1-SHYPLN-APP01_104295_4000_pdc1-ppcmv-vsa2 of VM PDC1-SHYPLN-APP01] - state [finished]
4000  293c  02/27 18:33:56 104295 RhevSDKWrapper::CVRhevOperations::deleteVMSnapshot() - Deleted snapshotId [332c7d70-e708-4a21-a9f0-08cbe432531e] for vm [4b754a1b-70db-4fe9-9648-2d5cbd538e24]
4000  293c  02/27 18:33:56 104295 CRhevInfo::DeleteVMSnapshot() - Snapshot [332c7d70-e708-4a21-a9f0-08cbe432531e] of VM [4b754a1b-70db-4fe9-9648-2d5cbd538e24] deleted successfully
4000  293c  02/27 18:33:56 104295 CRhevInfo::UnmountVM() - VM [PDC1-SHYPLN-APP01] unmounted successfully
4000  293c  02/27 18:33:56 104295 CVMInfo::GetLastVMError() - Unknown VMInfo error [0] for vm [PDC1-SHYPLN-APP01]
4000  293c  02/27 18:33:56 104295 CheckVMInfoError() - VM [PDC1-SHYPLN-APP01] Unknown VMInfo error [0]
4000  293c  02/27 18:33:56 104295 VSBkpController::AcquireStream() - Worker [3] Acquired stream id [9] rcid [187860]
4000  3794  02/27 18:34:17 104295 VSBkpController::MonitorProgress() - [4] VMs are being processed
4000  293c  02/27 18:34:26 104295 VSBkpWorker::SendBLRPreSnapVM() - There are no pairs in the DB with subclient id [0], VM Guid[4B754A1B-70DB-4FE9-9648-2D5CBD538E24]
4000  293c  02/27 18:34:26 104295 CRhevInfo::UnmountVM() - Disk Count to disconnect from Proxy: 0
4000  293c  02/27 18:34:26 104295 CRhevInfo::UnmountVM() - VM [PDC1-SHYPLN-APP01] unmounted successfully
4000  293c  02/27 18:34:26 104295 VSBkpWorker::RemoveCleanupString() - Removing Cleanup string [VSIDA -j 104295 -a 2:322 -vmHost "mod-dc01-prod-rhv-mgmt-01.mod.mil" -vmName "PDC1-SHYPLN-APP01" -vmGuid "4b754a1b-70db-4fe9-9648-2d5cbd538e24" -vmCleanup "332c7d70-e708-4a21-a9f0-08cbe432531e" ] from JobManager
4000  293c  02/27 18:34:26 104295 VSBkpController::RelinquishStream() - Worker [3] Relinquishing stream id [9] rcid [187860]
4000  293c  02/27 18:34:26 104295 VSBkpWorker::HandleVMComplete_Status() - Error backing up VM [PDC1-SHYPLN-APP01], failing the VM for this job
4000  293c  02/27 18:34:26 104295 vsJobMgr::updateVMBkpJobStatus() - Sending VM status for [3] virtual machines
4000  293c  02/27 18:34:26 104295 VSBkpController::SendGetNextVM() - Requesting Next VM from coordinator
4000  2be8  02/27 18:34:26 104295 VSBkpCoordinator::OnMsgVMBackupResult() - Received Status [2] for VM [PDC1-SHYPLN-APP01] from [pdc1-ppcmv-vsa2]
4000  2be8  02/27 18:34:26 104295 vsJobMgr::updateRegularBkpProgressBar() - Updating the progress bar [18]
4000  2be8  02/27 18:34:26 104295 VSBkpCoordinator::OnMsgVMBackupGetNextVM() - GetNextVM Request from [pdc1-ppcmv-vsa2]
4000  2be8  02/27 18:34:26 104295 VSBkpCoordinator::ProcessGetNextVMForAgent() - Selected VM [PDC1-SODI-APP01] for agent [pdc1-ppcmv-vsa2] with volume activity of [4]
4000  2be8  02/27 18:34:26 104295 VSBkpCoordinator::GiveVMsToAgent() - Sending [1] VMs to agent [pdc1-ppcmv-vsa2]
4000  2be8  02/27 18:34:26 104295 VSBkpCoordinator::GiveVMsToAgent() - Sending VM [PDC1-SODI-APP01] to agent [pdc1-ppcmv-vsa2]
4000  2834  02/27 18:34:26 104295 VSBkpController::OnMsgReceived() - Message [VirtualServer_VMCollectList] received from Server
4000  2834  02/27 18:34:26 104295 VSBkpController::OnMsgVMCollectList() - Received [1] VMs
4000  2834  02/27 18:34:26 104295 VSBkpController::OnMsgVMCollectList() - Received VM [PDC1-SODI-APP01]
4000  293c  02/27 18:34:26 104295 VSBkpController::_GetNextVM() - Returning VM [PDC1-SODI-APP01]
4000  293c  02/27 18:34:26 104295 VSBkpWorker::WorkerThread() - Worker [3] Processing VM [8] [PDC1-SODI-APP01]
4000  293c  02/27 18:34:26 104339 VSBkpWorker::ProcessVM Processing VM [PDC1-SODI-APP01] AppId [109] using child job [104339] and parent job [104295]
4000  293c  02/27 18:34:26 104295 VSBkpWorker::ProcessVM() - Processing VM [PDC1-SODI-APP01] AppId [109] using child job [104339] and parent job [104295]
4000  293c  02/27 18:34:26 104295 VSBkpController::GetIndexClient() - Opening Indexing connection
4000  293c  02/27 18:34:27 104295 IDXBROWSECL Populated browse request from CS = [<?xml version="1.0" encoding="UTF-8" standalone="no" ?><databrowse_BrowseRequest opType="0" pathType="0" userName=""><session sessionId="1709048066-80"/><entity _type_="7" applicationId="106" backupsetGUID="04462B78-AA57-487A-B6AD-3EC883549C50" backupsetId="94" clientId="244" commCellId="2" instanceId="2" name="PDC1-SODI-APP01" subclientGUID="9431CAC7-8F9E-450D-A87D-6499625554A8" subclientId="109"/><paths path="\"/><timeRange fromTime="0" toTime="1709048066"/><options DoNotCacheFilters="0" PreferContentServer="0" adjustPerLastDRTime="0" allowInfectedFilesRestore="0" browseFromCSDB="0" browseFromJobType="3" browseFromLatestJob="1" bulkOperation="0" bypassSubclientConfig="1" caseInsensitive="0" caseManagerDataCopy="0" createRestoreVectors="0" cycleBrowse="0" disableSnapOptimizer="0" doPrediction="0" downloadSystemScan="0" downloadTrueUpStubScanOutput="0" enforceSuperBrowse="0" fetchFileProperties="0" fixPaths="0" folderDelete="0" fsExtentBrowse="0" getACLs="0" hideEmptyExtents="0" imageBrowse="0" includeAgedData="0" includeAllParents="0" includeCheckSum="0" includeEndUserErasedItems="0" includeExtentCRC="0" includeMetadata="1" includeRunningJobs="0" includeSoftCommittedJobs="0" includeVersions="0" instantSend="0" internalReq="0" isLatestCycleBrowse="1" isOneTouchRestore="0" machineLiveBrowse="0" nasFilerType="0" nasSynthDirRestore="2" nasSynthRestore="0" nonRecursiveNASRestore="0" onePassRedundancy="0" onePassStubQuery="0" prepareSystemScan="0" pruneFromSource="0" queryAgedArchiveFileData="0" reCreateRestoreVector="0" refCopy="0" refCopyCloudMigration="0" refCopySF="0" relationshipBrowse="0" restoreIndex="1" sendBackListOfAfiles="0" sendDeletionTime="0" sendOutputToFile="0" sharedFolderBrowse="0" showDeletedFiles="0" showFavoriteAndShareInfo="0" showFolderSize="0" showLastValidBackup="0" showOnlyDeleted="0" showOnlyModified="0" showOnlyNew="0" showThumbnail="0" skipDataPrediction="0" skipIndexRestore="0" skipInvalidMimeClassification="0" skipLatestVersion="0" skipMountPoints="0" skipNasRenamedDirs="0" skipProgressMessage="0" skipSynthFullJobs="0" synthFull="0" tableViewBrowse="0" translateSyncPath="0" translateToVMReq="0" useLatestCycle="0" useUptoDateIndexOnly="1" verifyArchiverQuery="0" viewBackupCopy="0" vsDiskBrowse="1" vsExtentBrowse="0" vsFileBrowse="0" vsListVMs="0" vsLiveSyncBrowse="0" vsVolumeBrowse="0" vsaDiskLevelRestore="0" vsaFileLevelRestore="0"/><mode mode="4"/><ma _type_="3" clientName="PDC1PP-COM-MA2"/><advOptions applyStrictACL="0" copyPrecedence="0" datasourceId="0" includePsuedoItems="0" retryLimit="0" retryWaitSecs="300" skipACLChecks="0" skipUptodateCheck="0" stubAsData="0" timeoutSecs="300" userId="0" validateAfiles="1" vmCentricClient="0"><advConfig recallRequest="0"><browseAdvancedConfigReq commcellId="2" jobType="0"><additionalFlags flagType="9" value="&lt;?xml version=&quot;1.0&quot; encoding=&quot;UTF-8&quot; standalone=&quot;no&quot; ?>&lt;databrowse_JobInfoList>&lt;jobInfoList afileCtime=&quot;1708799883&quot; appId=&quot;109&quot; commcellId=&quot;2&quot; jobId=&quot;102223&quot;/>&lt;/databrowse_JobInfoList>"/></browseAdvancedConfigReq><extendedConfig><browseAdvConfigLiveBrowse><mountMa _type_="3"/></browseAdvConfigLiveBrowse></extendedConfig></advConfig></advOptions><queries queryId="0" type="0"><dataParam><paging firstNode="0" pageSize="4294967295" skipNode="0"/></dataParam></queries><applicationInfo><indexingInfo connectBackHost="" connectBackService="" extendedOptions="" idxAppType="200108" jobId="0" maMangled="PDC1PP-COM-MA2.MOD.MIL*PDC1PP-COM-MA2*8400" multiClientRequest="0" workerId="80"><indexdbList backupsetGuid="04462B78-AA57-487A-B6AD-3EC883549C50" idxAppType="0" idxDbEngineType="1" maMangledName="PDC1PP-COM-MA2.MOD.MIL*PDC1PP-COM-MA2*8400"><dbInfo DbIdentifer="04462B78-AA57-487A-B6AD-3EC883549C50"/></indexdbList><mainIndexDb backupsetGuid="04462B78-AA57-487A-B6AD-3EC883549C50" idxAppType="0" idxDbEngineType="1" maMangledName="PDC1PP-COM-MA2.MOD.MIL*PDC1PP-COM-MA2*8400"><dbInfo DbIdentifer="04462B78-AA57-487A-B6AD-3EC883549C50"/><subclientInfos appGuid="9431CAC7-8F9E-450D-A87D-6499625554A8" appId="109" latestIdxAfCtime="1708799883" minIdxAfCtime="1708798905"/></mainIndexDb><flags SynthFullStreamMode="0" browseFromCache="0" createRestVectors="0" crossComponentWorker="0" getVectorNames="0" includeVersions="0" instantSend="0" isRefCopyClient="0" mergeMultiClientBrowseData="0" multiEntityBrowse="0" populateCache="0" retentionBrowse="0" showFolderSize="0" showItemsMarkedDeleted="0" superBrowse="0" superBrowseNoLock="0" superBrowseWorker="0" syntheticFull="0"/></indexingInfo></applicationInfo></databrowse_BrowseRequest>]
4000  293c  02/27 18:34:27 104295 vsIndexClient::InitIdxBrowseClient() - Successfully initialized idxBrowse connection
4000  293c  02/27 18:34:27 104295 VSBkpWorker::CheckAndConvertJobToFull() - Previous backup job for VM [PDC1-SODI-APP01] Guid [48dd7855-8f6b-4cbe-b54a-32fe0ffa11f2] was [Streaming]
4000  293c  02/27 18:34:27 104295 VSBkpWorker::ProcessVM() - Metadata for VM [PDC1-SODI-APP01] components received from previous successful backup job
4000  293c  02/27 18:34:27 104295 VSBkpWorker::ProcessVM() - IndexName [3a7ad7f6-5150-475b-b003-b5efc719168b] Extent Size [512] ChangeId []
4000  293c  02/27 18:34:27 104295 VSBkpWorker::ProcessVM() - IndexName [b65ae147-41aa-4935-ae9a-3d4ca1174a2f] Extent Size [512] ChangeId []
4000  293c  02/27 18:34:27 104295 VSBkpWorker::ProcessVM() - IndexName [PDC1-SODI-APP01.ovf] Extent Size [20370] ChangeId []
4000  293c  02/27 18:34:27 104295 VSBkpWorker::ProcessVM() - IndexName [VMConfig.cvf] Extent Size [1141] ChangeId []
4000  293c  02/27 18:34:27 104295 VSBkpWorker::SendBLRPreSnapVM() - There are no pairs in the DB with subclient id [0], VM Guid[48DD7855-8F6B-4CBE-B54A-32FE0FFA11F2]
4000  293c  02/27 18:34:29 104295 CRhevInfo::_MountVM_rcb() - Mounting VM:[PDC1-SODI-APP01] with GUID:[48dd7855-8f6b-4cbe-b54a-32fe0ffa11f2]
4000  37e8  02/27 18:34:36 104295 RhevSDKWrapper::CVRhevOperations::pollForRhevJobCompletion() - Job Complete [b429b5c6-e615-49d5-8794-3cc4c1c1cf69] [Removing Snapshot _GX_BACKUP_PDC1-SEBS-APPUI02_104295_4000_pdc1-ppcmv-vsa2 of VM PDC1-SEBS-APPUI02] - state [finished]
4000  37e8  02/27 18:34:39 104295 RhevSDKWrapper::CVRhevOperations::deleteVMSnapshot() - Deleted snapshotId [4d42bcdd-e40b-4e9f-bbe9-bb25b0c52182] for vm [b904f74e-1a5d-4946-8876-52aae0ff9ff6]
4000  37e8  02/27 18:34:39 104295 CRhevInfo::DeleteVMSnapshot() - Snapshot [4d42bcdd-e40b-4e9f-bbe9-bb25b0c52182] of VM [b904f74e-1a5d-4946-8876-52aae0ff9ff6] deleted successfully
4000  37e8  02/27 18:34:39 104295 CRhevInfo::UnmountVM() - VM [PDC1-SEBS-APPUI02] unmounted successfully
4000  37e8  02/27 18:34:39 104295 CVMInfo::GetLastVMError() - Unknown VMInfo error [0] for vm [PDC1-SEBS-APPUI02]
4000  37e8  02/27 18:34:39 104295 CheckVMInfoError() - VM [PDC1-SEBS-APPUI02] Unknown VMInfo error [0]
4000  37e8  02/27 18:34:39 104295 VSBkpController::AcquireStream() - Worker [0] Acquired stream id [10] rcid [187861]
4000  37e8  02/27 18:34:41 104295 VSBkpWorker::SendBLRPreSnapVM() - There are no pairs in the DB with subclient id [0], VM Guid[B904F74E-1A5D-4946-8876-52AAE0FF9FF6]
4000  37e8  02/27 18:34:41 104295 CRhevInfo::UnmountVM() - Disk Count to disconnect from Proxy: 0
4000  37e8  02/27 18:34:41 104295 CRhevInfo::UnmountVM() - VM [PDC1-SEBS-APPUI02] unmounted successfully
4000  37e8  02/27 18:34:41 104295 VSBkpWorker::RemoveCleanupString() - Removing Cleanup string [VSIDA -j 104295 -a 2:322 -vmHost "mod-dc01-prod-rhv-mgmt-01.mod.mil" -vmName "PDC1-SEBS-APPUI02" -vmGuid "b904f74e-1a5d-4946-8876-52aae0ff9ff6" -vmCleanup "4d42bcdd-e40b-4e9f-bbe9-bb25b0c52182" ] from JobManager
4000  37e8  02/27 18:34:41 104295 VSBkpController::RelinquishStream() - Worker [0] Relinquishing stream id [10] rcid [187861]
4000  37e8  02/27 18:34:41 104295 VSBkpWorker::HandleVMComplete_Status() - Error backing up VM [PDC1-SEBS-APPUI02], failing the VM for this job
4000  37e8  02/27 18:34:41 104295 vsJobMgr::updateVMBkpJobStatus() - Sending VM status for [4] virtual machines
4000  37e8  02/27 18:34:41 104295 VSBkpController::SendGetNextVM() - Requesting Next VM from coordinator
4000  2be8  02/27 18:34:41 104295 VSBkpCoordinator::OnMsgVMBackupResult() - Received Status [2] for VM [PDC1-SEBS-APPUI02] from [pdc1-ppcmv-vsa2]
4000  2be8  02/27 18:34:41 104295 vsJobMgr::updateRegularBkpProgressBar() - Updating the progress bar [22]
4000  2be8  02/27 18:34:41 104295 VSBkpCoordinator::OnMsgVMBackupGetNextVM() - GetNextVM Request from [pdc1-ppcmv-vsa2]
4000  2be8  02/27 18:34:41 104295 VSBkpCoordinator::ProcessGetNextVMForAgent() - Selected VM [PDC1-SHYPFM-SUPP02] for agent [pdc1-ppcmv-vsa2] with volume activity of [4]
4000  2be8  02/27 18:34:41 104295 VSBkpCoordinator::GiveVMsToAgent() - Sending [1] VMs to agent [pdc1-ppcmv-vsa2]
4000  2be8  02/27 18:34:41 104295 VSBkpCoordinator::GiveVMsToAgent() - Sending VM [PDC1-SHYPFM-SUPP02] to agent [pdc1-ppcmv-vsa2]
4000  2834  02/27 18:34:41 104295 VSBkpController::OnMsgReceived() - Message [VirtualServer_VMCollectList] received from Server
4000  2834  02/27 18:34:41 104295 VSBkpController::OnMsgVMCollectList() - Received [1] VMs
4000  2834  02/27 18:34:41 104295 VSBkpController::OnMsgVMCollectList() - Received VM [PDC1-SHYPFM-SUPP02]
4000  37e8  02/27 18:34:41 104295 VSBkpController::_GetNextVM() - Returning VM [PDC1-SHYPFM-SUPP02]
4000  37e8  02/27 18:34:41 104295 VSBkpWorker::WorkerThread() - Worker [0] Processing VM [9] [PDC1-SHYPFM-SUPP02]
4000  37e8  02/27 18:34:41 104337 VSBkpWorker::ProcessVM Processing VM [PDC1-SHYPFM-SUPP02] AppId [116] using child job [104337] and parent job [104295]
4000  37e8  02/27 18:34:41 104295 VSBkpWorker::ProcessVM() - Processing VM [PDC1-SHYPFM-SUPP02] AppId [116] using child job [104337] and parent job [104295]
4000  37e8  02/27 18:34:42 104295 IDXBROWSECL Populated browse request from CS = [<?xml version="1.0" encoding="UTF-8" standalone="no" ?><databrowse_BrowseRequest opType="0" pathType="0" userName=""><session sessionId="1709048081-81"/><entity _type_="7" applicationId="106" backupsetGUID="9CDD0C6A-93C0-4D00-8AF5-2AC8CB640B7C" backupsetId="101" clientId="229" commCellId="2" instanceId="2" name="PDC1-SHYPFM-SUPP02" subclientGUID="E6D31999-2891-4526-BF12-845B701D35F6" subclientId="116"/><paths path="\"/><timeRange fromTime="0" toTime="1709048081"/><options DoNotCacheFilters="0" PreferContentServer="0" adjustPerLastDRTime="0" allowInfectedFilesRestore="0" browseFromCSDB="0" browseFromJobType="3" browseFromLatestJob="1" bulkOperation="0" bypassSubclientConfig="1" caseInsensitive="0" caseManagerDataCopy="0" createRestoreVectors="0" cycleBrowse="0" disableSnapOptimizer="0" doPrediction="0" downloadSystemScan="0" downloadTrueUpStubScanOutput="0" enforceSuperBrowse="0" fetchFileProperties="0" fixPaths="0" folderDelete="0" fsExtentBrowse="0" getACLs="0" hideEmptyExtents="0" imageBrowse="0" includeAgedData="0" includeAllParents="0" includeCheckSum="0" includeEndUserErasedItems="0" includeExtentCRC="0" includeMetadata="1" includeRunningJobs="0" includeSoftCommittedJobs="0" includeVersions="0" instantSend="0" internalReq="0" isLatestCycleBrowse="1" isOneTouchRestore="0" machineLiveBrowse="0" nasFilerType="0" nasSynthDirRestore="2" nasSynthRestore="0" nonRecursiveNASRestore="0" onePassRedundancy="0" onePassStubQuery="0" prepareSystemScan="0" pruneFromSource="0" queryAgedArchiveFileData="0" reCreateRestoreVector="0" refCopy="0" refCopyCloudMigration="0" refCopySF="0" relationshipBrowse="0" restoreIndex="1" sendBackListOfAfiles="0" sendDeletionTime="0" sendOutputToFile="0" sharedFolderBrowse="0" showDeletedFiles="0" showFavoriteAndShareInfo="0" showFolderSize="0" showLastValidBackup="0" showOnlyDeleted="0" showOnlyModified="0" showOnlyNew="0" showThumbnail="0" skipDataPrediction="0" skipIndexRestore="0" skipInvalidMimeClassification="0" skipLatestVersion="0" skipMountPoints="0" skipNasRenamedDirs="0" skipProgressMessage="0" skipSynthFullJobs="0" synthFull="0" tableViewBrowse="0" translateSyncPath="0" translateToVMReq="0" useLatestCycle="0" useUptoDateIndexOnly="1" verifyArchiverQuery="0" viewBackupCopy="0" vsDiskBrowse="1" vsExtentBrowse="0" vsFileBrowse="0" vsListVMs="0" vsLiveSyncBrowse="0" vsVolumeBrowse="0" vsaDiskLevelRestore="0" vsaFileLevelRestore="0"/><mode mode="4"/><ma _type_="3" clientName="PDC1PP-COM-MA2"/><advOptions applyStrictACL="0" copyPrecedence="0" datasourceId="0" includePsuedoItems="0" retryLimit="0" retryWaitSecs="300" skipACLChecks="0" skipUptodateCheck="0" stubAsData="0" timeoutSecs="300" userId="0" validateAfiles="1" vmCentricClient="0"><advConfig recallRequest="0"><browseAdvancedConfigReq commcellId="2" jobType="0"><additionalFlags flagType="9" value="&lt;?xml version=&quot;1.0&quot; encoding=&quot;UTF-8&quot; standalone=&quot;no&quot; ?>&lt;databrowse_JobInfoList>&lt;jobInfoList afileCtime=&quot;1708795276&quot; appId=&quot;116&quot; commcellId=&quot;2&quot; jobId=&quot;102220&quot;/>&lt;/databrowse_JobInfoList>"/></browseAdvancedConfigReq><extendedConfig><browseAdvConfigLiveBrowse><mountMa _type_="3"/></browseAdvConfigLiveBrowse></extendedConfig></advConfig></advOptions><queries queryId="0" type="0"><dataParam><paging firstNode="0" pageSize="4294967295" skipNode="0"/></dataParam></queries><applicationInfo><indexingInfo connectBackHost="" connectBackService="" extendedOptions="" idxAppType="200108" jobId="0" maMangled="PDC1PP-COM-MA2.MOD.MIL*PDC1PP-COM-MA2*8400" multiClientRequest="0" workerId="81"><indexdbList backupsetGuid="9CDD0C6A-93C0-4D00-8AF5-2AC8CB640B7C" idxAppType="0" idxDbEngineType="1" maMangledName="PDC1PP-COM-MA2.MOD.MIL*PDC1PP-COM-MA2*8400"><dbInfo DbIdentifer="9CDD0C6A-93C0-4D00-8AF5-2AC8CB640B7C"/></indexdbList><mainIndexDb backupsetGuid="9CDD0C6A-93C0-4D00-8AF5-2AC8CB640B7C" idxAppType="0" idxDbEngineType="1" maMangledName="PDC1PP-COM-MA2.MOD.MIL*PDC1PP-COM-MA2*8400"><dbInfo DbIdentifer="9CDD0C6A-93C0-4D00-8AF5-2AC8CB640B7C"/><subclientInfos appGuid="E6D31999-2891-4526-BF12-845B701D35F6" appId="116" latestIdxAfCtime="1708795276" minIdxAfCtime="1708794082"/></mainIndexDb><flags SynthFullStreamMode="0" browseFromCache="0" createRestVectors="0" crossComponentWorker="0" getVectorNames="0" includeVersions="0" instantSend="0" isRefCopyClient="0" mergeMultiClientBrowseData="0" multiEntityBrowse="0" populateCache="0" retentionBrowse="0" showFolderSize="0" showItemsMarkedDeleted="0" superBrowse="0" superBrowseNoLock="0" superBrowseWorker="0" syntheticFull="0"/></indexingInfo></applicationInfo></databrowse_BrowseRequest>]
4000  37e8  02/27 18:34:42 104295 vsIndexClient::InitIdxBrowseClient() - Successfully initialized idxBrowse connection
4000  37e8  02/27 18:34:42 104295 VSBkpWorker::CheckAndConvertJobToFull() - Previous backup job for VM [PDC1-SHYPFM-SUPP02] Guid [4da5667a-2b8d-403e-ad1f-be0a831520a4] was [Streaming]
4000  37e8  02/27 18:34:42 104295 VSBkpWorker::ProcessVM() - Metadata for VM [PDC1-SHYPFM-SUPP02] components received from previous successful backup job
4000  37e8  02/27 18:34:42 104295 VSBkpWorker::ProcessVM() - IndexName [681e8578-2b18-439e-af4b-a34de2723213] Extent Size [512] ChangeId []
4000  37e8  02/27 18:34:42 104295 VSBkpWorker::ProcessVM() - IndexName [c144dc3d-f578-4bcf-941d-7288394dc843] Extent Size [512] ChangeId []
4000  37e8  02/27 18:34:42 104295 VSBkpWorker::ProcessVM() - IndexName [PDC1-SHYPFM-SUPP02.ovf] Extent Size [20030] ChangeId []
4000  37e8  02/27 18:34:42 104295 VSBkpWorker::ProcessVM() - IndexName [VMConfig.cvf] Extent Size [922] ChangeId []
4000  37e8  02/27 18:34:42 104295 VSBkpWorker::SendBLRPreSnapVM() - There are no pairs in the DB with subclient id [0], VM Guid[4DA5667A-2B8D-403E-AD1F-BE0A831520A4]
4000  37e8  02/27 18:34:44 104295 CRhevInfo::_MountVM_rcb() - Mounting VM:[PDC1-SHYPFM-SUPP02] with GUID:[4da5667a-2b8d-403e-ad1f-be0a831520a4]
4000  293c  02/27 18:34:45 104295 CRhevInfo::_MountVM_rcb() - Creating snapshot with description [_GX_BACKUP_PDC1-SODI-APP01_104295_4000_pdc1-ppcmv-vsa2]
4000  3794  02/27 18:34:51 104295 VSBkpController::MonitorProgress() - [4] VMs are being processed
4000  2be8  02/27 18:34:51 104295 VSBkpCoordinator::OnIdle_Running() - Waiting for [18] VMs to be processed.  [PDC1-SODQ-APP01, PDC1-SHYPFDME-APP01, PDC1-SHYPLN-SUPP01...]
4000  2be8  02/27 18:34:51 104295 VSBkpCoordinator::OnIdle_Running() - [13] have not been dispatched
4000  2be8  02/27 18:34:51 104295 VSBkpCoordinator::DumpStreamInfo() - StreamId =   5, RCID = 187851, ReservationId = 180891, MediaAgent = [PDC1PP-COM-MA1], Agent = [pdc1-ppcmv-vsa2]  [Assigned]
4000  2be8  02/27 18:34:51 104295 VSBkpCoordinator::DumpStreamInfo() - StreamId =   7, RCID = 187858, ReservationId = 180896, MediaAgent = [PDC1PP-COM-MA1], Agent = [pdc1-ppcmv-vsa01]  [Assigned]
4000  2be8  02/27 18:34:51 104295 VSBkpCoordinator::DumpStreamInfo() - StreamId =   8, RCID = 187859, ReservationId = 180897, MediaAgent = [PDC1PP-COM-MA1], Agent = [pdc1-ppcmv-vsa2]  [Assigned]
4000  2be8  02/27 18:34:51 104295 VSBkpCoordinator::DumpStreamInfo() - StreamId =   9, RCID = 187860, ReservationId = 180898, MediaAgent = [PDC1PP-COM-MA1], Agent = [pdc1-ppcmv-vsa2]  [Assigned]
4000  2be8  02/27 18:34:51 104295 VSBkpCoordinator::DumpStreamInfo() - StreamId =  10, RCID = 187861, ReservationId = 180899, MediaAgent = [PDC1PP-COM-MA1], Agent = [pdc1-ppcmv-vsa2]  [Assigned]
4000  2be8  02/27 18:34:51 104295 VSBkpCoordinator::OnIdle_Running() - Agent [pdc1-ppcmv-vsa01] is [Running]  1 VMs   1 Streams
4000  2be8  02/27 18:34:51 104295 VSBkpCoordinator::OnIdle_Running() - Agent [pdc1-ppcmv-vsa2] is [Running]  4 VMs   4 Streams
4000  293c  02/27 18:34:52 104295 RhevSDKWrapper::CVRhevOperations::pollVMSnapshotStatus() - Correlation Id [104295_4000_1709048087] does not match with job [Creating VM Snapshot _GX_BACKUP_PDC1-SODI-APP01_104295_4000_pdc1-ppcmv-vsa2 for VM PDC1-SODI-APP01][253655ca-76ab-4cb6-9be6-e8330063181b]
4000  37e8  02/27 18:34:56 104295 CRhevInfo::_MountVM_rcb() - Creating snapshot with description [_GX_BACKUP_PDC1-SHYPFM-SUPP02_104295_4000_pdc1-ppcmv-vsa2]
4000  1e9c  02/27 18:34:57 104295 stat- ID [Datastore Read [MOD-DC01-RHV-PREPROD-APP-STOR-01]], Bytes [965492606251], Time [641.074085] Sec(s), Average Speed [1436.285638] MB/Sec
4000  3174  02/27 18:34:57 104295 stat- ID [calcCRC], Bytes [516112252928], Time [379.578387] Sec(s), Average Speed [1296.709764] MB/Sec
4000  1294  02/27 18:34:57 104295 stat- ID [readdisk], Bytes [516112515513], Time [606.170247] Sec(s), Average Speed [811.988468] MB/Sec
4000  3174  02/27 18:34:57 104295 stat- ID [readCRC], Samples [1968812], Time [12.666060] Sec(s), Average [0.000006] Sec/Sample
4000  37e8  02/27 18:35:02 104295 RhevSDKWrapper::CVRhevOperations::pollVMSnapshotStatus() - Correlation Id [104295_4000_1709048098] does not match with job [Creating VM Snapshot _GX_BACKUP_PDC1-SHYPFM-SUPP02_104295_4000_pdc1-ppcmv-vsa2 for VM PDC1-SHYPFM-SUPP02][0e25f734-acd2-4741-a0a6-05e5b8989756]
4000  293c  02/27 18:35:08 104295 RhevSDKWrapper::CVRhevOperations::checkSnapshotStatusCallBack() - snapshot status [ok] ready
4000  293c  02/27 18:35:11 104295 RhevSDKWrapper::CVRhevOperations::createVMSnapshot() - VM Snapshot created successfully. ID[1f99f54a-3c49-4040-91f8-e01064e4009e] Desc[_GX_BACKUP_PDC1-SODI-APP01_104295_4000_pdc1-ppcmv-vsa2]
4000  293c  02/27 18:35:11 104295 RhevSDKWrapper::CVRhevSDKWrapper::createVMSnapshot() - CreateVM Snapshot successful
4000  293c  02/27 18:35:11 104295 CRhevInfo::_MountVM_rcb() - Snapshot [1f99f54a-3c49-4040-91f8-e01064e4009e] created for VM [PDC1-SODI-APP01] successfully
4000  293c  02/27 18:35:11 104295 VSBkpWorker::SaveCleanupString() - Saving Cleanup string [VSIDA -j 104295 -a 2:322 -vmHost "mod-dc01-prod-rhv-mgmt-01.mod.mil" -vmName "PDC1-SODI-APP01" -vmGuid "48dd7855-8f6b-4cbe-b54a-32fe0ffa11f2" -vmCleanup "1f99f54a-3c49-4040-91f8-e01064e4009e" ] with JobManager
4000  293c  02/27 18:35:11 104295 VMCleaner::LookupEntity() - Looking up [C:\Program Files\Commvault\ContentStore\iDataAgent\JobResults\CV_JobResults\14D8A66B-9B0C-4C7B-BC4D-762A7F6F7E33\BACKUP\4000-vsbkp.exe\VM\48dd7855-8f6b-4cbe-b54a-32fe0ffa11f2]...not found!
4000  293c  02/27 18:35:11 104295 CRhevInfo::SaveVMConfigFile() - Wrote vm config file successfully to [C:\Program Files\Commvault\ContentStore\iDataAgent\JobResults\CV_JobResults\iDataAgent\VirtualServerAgent\2\322\(48dd7855-8f6b-4cbe-b54a-32fe0ffa11f2)\PDC1-SODI-APP01.ovf]
4000  293c  02/27 18:35:11 104295 CRhevInfo::_MountVM_rcb() - VM config file saved successfully
4000  293c  02/27 18:35:17 104295 RhevSDKWrapper::CVRhevOperations::attachDisk() - Attached disk [3a7ad7f6-5150-475b-b003-b5efc719168b] snapshotid [1f99f54a-3c49-4040-91f8-e01064e4009e] to VMid [14D8A66B-9B0C-4C7B-BC4D-762A7F6F7E33]
4000  293c  02/27 18:35:17 104295 CRhevInfo::AttachAndActivateDisk() - Disk [3a7ad7f6-5150-475b-b003-b5efc719168b] attached successfully
4000  293c  02/27 18:35:17 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  37e8  02/27 18:35:17 104295 RhevSDKWrapper::CVRhevOperations::checkSnapshotStatusCallBack() - snapshot status [ok] ready

 

Userlevel 2
Badge +4

@Mansour_Nour 

Thank you for update. 

 

From the above logs, I can see the issue is coming after disks are getting attached and after that there is no progress. 

4000  37e8  02/27 18:31:49 104295 CRhevInfo::AttachAndActivateDisk() - Disk [06aade11-7114-4e47-826c-1b28e537f031] attached successfully
4000  37e8  02/27 18:31:49 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning
4000  37e8  02/27 18:31:54 104295 CDiskMapperWindows::PostAttachDisk() - Did not find any new disks, rescanning

Could you please the OS for the access node you are using?

What is the up time for the access node.

Have you tried to reboot the access node an tried backups.

 

I would suggest to reboot the access node and try the backup and if you are still seeing the issue I would suggest you to raise a support case to check further. 

 

Badge +4

Hi @nishas 

hope everything is going well at your end.

the same issue still occurs on multiple VMS every day.

not the same vms are failing, every time the backup runs different vms are failing

an i have checked the logs is it the same as the one above in the older comment.

VSA Proxy was rebooted and the issue still occurs.

 

any ideas?

Userlevel 2
Badge +4

@Mansour_Nour 

Can you please go ahead and raise a support case to check further.

 

Reply