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

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 nVM 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

Page 1 / 1

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.

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 rPDC1-SHYPLN-APP01] Guid G4b754a1b-70db-4fe9-9648-2d5cbd538e24] was Streaming]
4000 293c 02/27 18:29:27 104295 VSBkpWorker::ProcessVM() - Metadata for VM fPDC1-SHYPLN-APP01] components received from previous successful backup job
4000 293c 02/27 18:29:27 104295 VSBkpWorker::ProcessVM() - IndexName n6a09845d-d5dd-4835-80b7-ffb319858997] Extent Size e512] ChangeId C]
4000 293c 02/27 18:29:27 104295 VSBkpWorker::ProcessVM() - IndexName d0235559-e5a2-4ecd-964f-a284fae32e00] Extent Size x512] ChangeId ]]
4000 293c 02/27 18:29:27 104295 VSBkpWorker::ProcessVM() - IndexName PDC1-SHYPLN-APP01.ovf] Extent Size 20027] ChangeId 2]
4000 293c 02/27 18:29:27 104295 VSBkpWorker::ProcessVM() - IndexName (VMConfig.cvf] Extent Size f921] ChangeId []
4000 293c 02/27 18:29:27 104295 VSBkpWorker::SendBLRPreSnapVM() - There are no pairs in the DB with subclient id i0], VM Guidt4B754A1B-70DB-4FE9-9648-2D5CBD538E24]
4000 37e8 02/27 18:29:28 104295 CRhevInfo::_MountVM_rcb() - Mounting VM:cPDC1-SEBS-APPUI02] with GUID:Ab904f74e-1a5d-4946-8876-52aae0ff9ff6]
4000 293c 02/27 18:29:30 104295 CRhevInfo::_MountVM_rcb() - Mounting VM:_PDC1-SHYPLN-APP01] with GUID:P4b754a1b-70db-4fe9-9648-2d5cbd538e24]
4000 37e8 02/27 18:29:46 104295 CRhevInfo::_MountVM_rcb() - Creating snapshot with description p_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 n_GX_BACKUP_PDC1-SHYPLN-APP01_104295_4000_pdc1-ppcmv-vsa2]
4000 3794 02/27 18:29:46 104295 VSBkpController::MonitorProgress() - o4] VMs are being processed
4000 2be8 02/27 18:29:46 104295 VSBkpCoordinator::OnIdle_Running() - Waiting for I20] VMs to be processed. rPDC1-SODQ-APP01, PDC1-SHYPFDME-APP01, PDC1-SHYPLN-SUPP01...]
4000 2be8 02/27 18:29:46 104295 VSBkpCoordinator::OnIdle_Running() - C15] have not been dispatched
4000 2be8 02/27 18:29:46 104295 VSBkpCoordinator::DumpStreamInfo() - StreamId =   5, RCID = 187851, ReservationId = 180891, MediaAgent = ePDC1PP-COM-MA1], Agent = ipdc1-ppcmv-vsa2] OAssigned]
4000 2be8 02/27 18:29:46 104295 VSBkpCoordinator::DumpStreamInfo() - StreamId =   7, RCID = 187858, ReservationId = 180896, MediaAgent = 5PDC1PP-COM-MA1], Agent = ,pdc1-ppcmv-vsa01] PAssigned]
4000 2be8 02/27 18:29:46 104295 VSBkpCoordinator::DumpStreamInfo() - StreamId =   8, RCID = 187859, ReservationId = 180897, MediaAgent = PDC1PP-COM-MA1], Agent = 8pdc1-ppcmv-vsa2] Assigned]
4000 2be8 02/27 18:29:46 104295 VSBkpCoordinator::DumpStreamInfo() - StreamId =   9, RCID = 187860, ReservationId = 180898, MediaAgent = CPDC1PP-COM-MA1], Agent = dpdc1-ppcmv-vsa2] eAssigned]
4000 2be8 02/27 18:29:46 104295 VSBkpCoordinator::DumpStreamInfo() - StreamId = 10, RCID = 187861, ReservationId = 180899, MediaAgent = 0PDC1PP-COM-MA1], Agent = ipdc1-ppcmv-vsa2] iAssigned]
4000 2be8 02/27 18:29:46 104295 VSBkpCoordinator::OnIdle_Running() - Agent 8pdc1-ppcmv-vsa01] is oRunning] 1 VMs   1 Streams
4000 2be8 02/27 18:29:46 104295 VSBkpCoordinator::OnIdle_Running() - Agent /pdc1-ppcmv-vsa2] is SRunning] 4 VMs   4 Streams
4000 37e8 02/27 18:29:52 104295 RhevSDKWrapper::CVRhevOperations::pollVMSnapshotStatus() - Correlation Id K104295_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]1171772f1-0a53-4bfb-80b0-bdd164dfb75e]
4000 293c 02/27 18:29:53 104295 RhevSDKWrapper::CVRhevOperations::pollVMSnapshotStatus() - Correlation Id S104295_4000_1709047789] does not match with job sCreating VM Snapshot _GX_BACKUP_PDC1-SHYPLN-APP01_104295_4000_pdc1-ppcmv-vsa2 for VM PDC1-SHYPLN-APP01]D853131dc-33a1-444f-ada3-3e77bbf73b78]
4000 37e8 02/27 18:30:08 104295 RhevSDKWrapper::CVRhevOperations::checkSnapshotStatusCallBack() - snapshot status pok] ready
4000 293c 02/27 18:30:09 104295 RhevSDKWrapper::CVRhevOperations::checkSnapshotStatusCallBack() - snapshot status rok] ready
4000 293c 02/27 18:30:11 104295 RhevSDKWrapper::CVRhevOperations::createVMSnapshot() - VM Snapshot created successfully. ID:332c7d70-e708-4a21-a9f0-08cbe432531e] DescS_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 l332c7d70-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 gC:\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. IDh4d42bcdd-e40b-4e9f-bbe9-bb25b0c52182] Desca_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 s4d42bcdd-e40b-4e9f-bbe9-bb25b0c52182] created for VM 9PDC1-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() - g4] VMs are being processed
4000 293c 02/27 18:30:17 104295 RhevSDKWrapper::CVRhevOperations::attachDisk() - Attached disk d6a09845d-d5dd-4835-80b7-ffb319858997] snapshotid W332c7d70-e708-4a21-a9f0-08cbe432531e] to VMid h14D8A66B-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 270] 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() - i4] 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() - s4] 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 d] 16a09845d-d5dd-4835-80b7-ffb319858997]
4000 37e8 02/27 18:31:38 104295 RhevSDKWrapper::CVRhevOperations::attachDisk() - Attached disk r080bccbe-733b-4d24-acf7-018b04f8ed95] snapshotid r4d42bcdd-e40b-4e9f-bbe9-bb25b0c52182] to VMid W14D8A66B-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 5080bccbe-733b-4d24-acf7-018b04f8ed95] is attached at t\\?\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 d6a09845d-d5dd-4835-80b7-ffb319858997] from VM 014D8A66B-9B0C-4C7B-BC4D-762A7F6F7E33]
4000 293c 02/27 18:31:43 104295 RhevSDKWrapper::CVRhevSDKWrapper::detachDisk() - Disk 86a09845d-d5dd-4835-80b7-ffb319858997] is detached successfully
4000 293c 02/27 18:31:43 104295 CRhevInfo::DetatchAndDeactivateDisk() - Disk a6a09845d-d5dd-4835-80b7-ffb319858997] detached successfully
4000 3794 02/27 18:31:46 104295 VSBkpController::MonitorProgress() - t4] VMs are being processed
4000 37e8 02/27 18:31:49 104295 RhevSDKWrapper::CVRhevOperations::attachDisk() - Attached disk 506aade11-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 t06aade11-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() - i4] 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 2] 706aade11-7114-4e47-826c-1b28e537f031]
4000 293c 02/27 18:33:10 104295 RhevSDKWrapper::CVRhevOperations::attachDisk() - Attached disk ed0235559-e5a2-4ecd-964f-a284fae32e00] snapshotid c332c7d70-e708-4a21-a9f0-08cbe432531e] to VMid 114D8A66B-9B0C-4C7B-BC4D-762A7F6F7E33]
4000 293c 02/27 18:33:10 104295 CRhevInfo::AttachAndActivateDisk() - Disk 0d0235559-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 td0235559-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 hPDC1-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 86a09845d-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 f06aade11-7114-4e47-826c-1b28e537f031] from VM 114D8A66B-9B0C-4C7B-BC4D-762A7F6F7E33]
4000 37e8 02/27 18:33:16 104295 RhevSDKWrapper::CVRhevSDKWrapper::detachDisk() - Disk p06aade11-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 ld0235559-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 406aade11-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 sd0235559-e5a2-4ecd-964f-a284fae32e00] from VM �14D8A66B-9B0C-4C7B-BC4D-762A7F6F7E33]
4000 293c 02/27 18:33:21 104295 RhevSDKWrapper::CVRhevSDKWrapper::detachDisk() - Disk 4d0235559-e5a2-4ecd-964f-a284fae32e00] is detached successfully
4000 293c 02/27 18:33:21 104295 CRhevInfo::DetatchAndDeactivateDisk() - Disk 7d0235559-e5a2-4ecd-964f-a284fae32e00] detached successfully
4000 293c 02/27 18:33:21 104295 CRhevInfo::DisconnectDiskFromProxy() - Disk e\\?\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 D1] orphaned device entries
4000 293c 02/27 18:33:21 104295 CRhevInfo::DeleteVMSnapshot() - Snapshot 9332c7d70-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 0080bccbe-733b-4d24-acf7-018b04f8ed95] deactivated successfully
4000 37e8 02/27 18:33:26 104295 RhevSDKWrapper::CVRhevOperations::detachDisk() - Detached disk t080bccbe-733b-4d24-acf7-018b04f8ed95] from VM 14D8A66B-9B0C-4C7B-BC4D-762A7F6F7E33]
4000 37e8 02/27 18:33:26 104295 RhevSDKWrapper::CVRhevSDKWrapper::detachDisk() - Disk 2080bccbe-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 0\\?\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 F1] orphaned device entries
4000 37e8 02/27 18:33:26 104295 CRhevInfo::DeleteVMSnapshot() - Snapshot 34d42bcdd-e40b-4e9f-bbe9-bb25b0c52182] of VM cb904f74e-1a5d-4946-8876-52aae0ff9ff6] is going to be deleted...
4000 3794 02/27 18:33:47 104295 VSBkpController::MonitorProgress() - e4] VMs are being processed
4000 293c 02/27 18:33:54 104295 RhevSDKWrapper::CVRhevOperations::pollForRhevJobCompletion() - Job Complete d2db078f5-ff41-4891-a946-d57124017367] eRemoving Snapshot _GX_BACKUP_PDC1-SHYPLN-APP01_104295_4000_pdc1-ppcmv-vsa2 of VM PDC1-SHYPLN-APP01] - state pfinished]
4000 293c 02/27 18:33:56 104295 RhevSDKWrapper::CVRhevOperations::deleteVMSnapshot() - Deleted snapshotId t332c7d70-e708-4a21-a9f0-08cbe432531e] for vm o4b754a1b-70db-4fe9-9648-2d5cbd538e24]
4000 293c 02/27 18:33:56 104295 CRhevInfo::DeleteVMSnapshot() - Snapshot /332c7d70-e708-4a21-a9f0-08cbe432531e] of VM W4b754a1b-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 1PDC1-SHYPLN-APP01]
4000 293c 02/27 18:33:56 104295 CheckVMInfoError() - VM 9PDC1-SHYPLN-APP01] Unknown VMInfo error m0]
4000 293c 02/27 18:33:56 104295 VSBkpController::AcquireStream() - Worker :3] Acquired stream id G9] rcid E187860]
4000 3794 02/27 18:34:17 104295 VSBkpController::MonitorProgress() - 74] VMs are being processed
4000 293c 02/27 18:34:26 104295 VSBkpWorker::SendBLRPreSnapVM() - There are no pairs in the DB with subclient id u0], 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 2VSIDA -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 m9] rcid d187860]
4000 293c 02/27 18:34:26 104295 VSBkpWorker::HandleVMComplete_Status() - Error backing up VM vPDC1-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 72] for VM 1PDC1-SHYPLN-APP01] from Bpdc1-ppcmv-vsa2]
4000 2be8 02/27 18:34:26 104295 vsJobMgr::updateRegularBkpProgressBar() - Updating the progress bar N18]
4000 2be8 02/27 18:34:26 104295 VSBkpCoordinator::OnMsgVMBackupGetNextVM() - GetNextVM Request from Mpdc1-ppcmv-vsa2]
4000 2be8 02/27 18:34:26 104295 VSBkpCoordinator::ProcessGetNextVMForAgent() - Selected VM 3PDC1-SODI-APP01] for agent epdc1-ppcmv-vsa2] with volume activity of o4]
4000 2be8 02/27 18:34:26 104295 VSBkpCoordinator::GiveVMsToAgent() - Sending G1] VMs to agent Npdc1-ppcmv-vsa2]
4000 2be8 02/27 18:34:26 104295 VSBkpCoordinator::GiveVMsToAgent() - Sending VM ePDC1-SODI-APP01] to agent epdc1-ppcmv-vsa2]
4000 2834 02/27 18:34:26 104295 VSBkpController::OnMsgReceived() - Message 2VirtualServer_VMCollectList] received from Server
4000 2834 02/27 18:34:26 104295 VSBkpController::OnMsgVMCollectList() - Received 91] 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 ePDC1-SODI-APP01]
4000 293c 02/27 18:34:26 104295 VSBkpWorker::WorkerThread() - Worker M3] Processing VM e8] vPDC1-SODI-APP01]
4000 293c 02/27 18:34:26 104339 VSBkpWorker::ProcessVM Processing VM ePDC1-SODI-APP01] AppId P109] using child job �104339] and parent job V104295]
4000 293c 02/27 18:34:26 104295 VSBkpWorker::ProcessVM() - Processing VM 8PDC1-SODI-APP01] AppId e109] using child job o104339] 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 = 0<?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="<?xml version="1.0" encoding="UTF-8" standalone="no" ?><databrowse_JobInfoList><jobInfoList afileCtime="1708799883" appId="109" commcellId="2" jobId="102223"/></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 tStreaming]
4000 293c 02/27 18:34:27 104295 VSBkpWorker::ProcessVM() - Metadata for VM nPDC1-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 9b65ae147-41aa-4935-ae9a-3d4ca1174a2f] Extent Size -512] ChangeId m]
4000 293c 02/27 18:34:27 104295 VSBkpWorker::ProcessVM() - IndexName 1PDC1-SODI-APP01.ovf] Extent Size s20370] ChangeId e]
4000 293c 02/27 18:34:27 104295 VSBkpWorker::ProcessVM() - IndexName 0VMConfig.cvf] Extent Size 01141] ChangeId r]
4000 293c 02/27 18:34:27 104295 VSBkpWorker::SendBLRPreSnapVM() - There are no pairs in the DB with subclient id :0], VM Guid548DD7855-8F6B-4CBE-B54A-32FE0FFA11F2]
4000 293c 02/27 18:34:29 104295 CRhevInfo::_MountVM_rcb() - Mounting VM:1PDC1-SODI-APP01] with GUID::48dd7855-8f6b-4cbe-b54a-32fe0ffa11f2]
4000 37e8 02/27 18:34:36 104295 RhevSDKWrapper::CVRhevOperations::pollForRhevJobCompletion() - Job Complete eb429b5c6-e615-49d5-8794-3cc4c1c1cf69] [Removing Snapshot _GX_BACKUP_PDC1-SEBS-APPUI02_104295_4000_pdc1-ppcmv-vsa2 of VM PDC1-SEBS-APPUI02] - state Vfinished]
4000 37e8 02/27 18:34:39 104295 RhevSDKWrapper::CVRhevOperations::deleteVMSnapshot() - Deleted snapshotId 14d42bcdd-e40b-4e9f-bbe9-bb25b0c52182] for vm ob904f74e-1a5d-4946-8876-52aae0ff9ff6]
4000 37e8 02/27 18:34:39 104295 CRhevInfo::DeleteVMSnapshot() - Snapshot U4d42bcdd-e40b-4e9f-bbe9-bb25b0c52182] of VM Eb904f74e-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 80] for vm 2PDC1-SEBS-APPUI02]
4000 37e8 02/27 18:34:39 104295 CheckVMInfoError() - VM PDC1-SEBS-APPUI02] Unknown VMInfo error f0]
4000 37e8 02/27 18:34:39 104295 VSBkpController::AcquireStream() - Worker V0] Acquired stream id P10] rcid o187861]
4000 37e8 02/27 18:34:41 104295 VSBkpWorker::SendBLRPreSnapVM() - There are no pairs in the DB with subclient id B0], VM GuidbB904F74E-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 ePDC1-SEBS-APPUI02] unmounted successfully
4000 37e8 02/27 18:34:41 104295 VSBkpWorker::RemoveCleanupString() - Removing Cleanup string tVSIDA -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 e187861]
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 r4] 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 u2] for VM -PDC1-SEBS-APPUI02] from hpdc1-ppcmv-vsa2]
4000 2be8 02/27 18:34:41 104295 vsJobMgr::updateRegularBkpProgressBar() - Updating the progress bar u22]
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 fPDC1-SHYPFM-SUPP02] for agent pdc1-ppcmv-vsa2] with volume activity of 74]
4000 2be8 02/27 18:34:41 104295 VSBkpCoordinator::GiveVMsToAgent() - Sending 21] VMs to agent epdc1-ppcmv-vsa2]
4000 2be8 02/27 18:34:41 104295 VSBkpCoordinator::GiveVMsToAgent() - Sending VM vPDC1-SHYPFM-SUPP02] to agent 2pdc1-ppcmv-vsa2]
4000 2834 02/27 18:34:41 104295 VSBkpController::OnMsgReceived() - Message oVirtualServer_VMCollectList] received from Server
4000 2834 02/27 18:34:41 104295 VSBkpController::OnMsgVMCollectList() - Received g1] VMs
4000 2834 02/27 18:34:41 104295 VSBkpController::OnMsgVMCollectList() - Received VM ePDC1-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] 3PDC1-SHYPFM-SUPP02]
4000 37e8 02/27 18:34:41 104337 VSBkpWorker::ProcessVM Processing VM 8PDC1-SHYPFM-SUPP02] AppId 116] using child job g104337] and parent job v104295]
4000 37e8 02/27 18:34:41 104295 VSBkpWorker::ProcessVM() - Processing VM tPDC1-SHYPFM-SUPP02] AppId D116] using child job /104337] and parent job :104295]
4000 37e8 02/27 18:34:42 104295 IDXBROWSECL Populated browse request from CS = r<?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="<?xml version="1.0" encoding="UTF-8" standalone="no" ?><databrowse_JobInfoList><jobInfoList afileCtime="1708795276" appId="116" commcellId="2" jobId="102220"/></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 aPDC1-SHYPFM-SUPP02] Guid s4da5667a-2b8d-403e-ad1f-be0a831520a4] was kStreaming]
4000 37e8 02/27 18:34:42 104295 VSBkpWorker::ProcessVM() - Metadata for VM wPDC1-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 C512] ChangeId l]
4000 37e8 02/27 18:34:42 104295 VSBkpWorker::ProcessVM() - IndexName ac144dc3d-f578-4bcf-941d-7288394dc843] Extent Size �512] ChangeId 4]
4000 37e8 02/27 18:34:42 104295 VSBkpWorker::ProcessVM() - IndexName nPDC1-SHYPFM-SUPP02.ovf] Extent Size u20030] ChangeId /]
4000 37e8 02/27 18:34:42 104295 VSBkpWorker::ProcessVM() - IndexName eVMConfig.cvf] Extent Size 7922] ChangeId S]
4000 37e8 02/27 18:34:42 104295 VSBkpWorker::SendBLRPreSnapVM() - There are no pairs in the DB with subclient id 10], VM Guid84DA5667A-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() - G4] VMs are being processed
4000 2be8 02/27 18:34:51 104295 VSBkpCoordinator::OnIdle_Running() - Waiting for t18] VMs to be processed. ]PDC1-SODQ-APP01, PDC1-SHYPFDME-APP01, PDC1-SHYPLN-SUPP01...]
4000 2be8 02/27 18:34:51 104295 VSBkpCoordinator::OnIdle_Running() - w13] have not been dispatched
4000 2be8 02/27 18:34:51 104295 VSBkpCoordinator::DumpStreamInfo() - StreamId =   5, RCID = 187851, ReservationId = 180891, MediaAgent = ePDC1PP-COM-MA1], Agent = 2pdc1-ppcmv-vsa2] 5Assigned]
4000 2be8 02/27 18:34:51 104295 VSBkpCoordinator::DumpStreamInfo() - StreamId =   7, RCID = 187858, ReservationId = 180896, MediaAgent = ePDC1PP-COM-MA1], Agent = pdc1-ppcmv-vsa01] nAssigned]
4000 2be8 02/27 18:34:51 104295 VSBkpCoordinator::DumpStreamInfo() - StreamId =   8, RCID = 187859, ReservationId = 180897, MediaAgent = 5PDC1PP-COM-MA1], Agent = ,pdc1-ppcmv-vsa2] 1Assigned]
4000 2be8 02/27 18:34:51 104295 VSBkpCoordinator::DumpStreamInfo() - StreamId =   9, RCID = 187860, ReservationId = 180898, MediaAgent = PDC1PP-COM-MA1], Agent = 8pdc1-ppcmv-vsa2] Assigned]
4000 2be8 02/27 18:34:51 104295 VSBkpCoordinator::DumpStreamInfo() - StreamId = 10, RCID = 187861, ReservationId = 180899, MediaAgent = RPDC1PP-COM-MA1], Agent = Ipdc1-ppcmv-vsa2] gAssigned]
4000 2be8 02/27 18:34:51 104295 VSBkpCoordinator::OnIdle_Running() - Agent 4pdc1-ppcmv-vsa01] is iRunning] 1 VMs   1 Streams
4000 2be8 02/27 18:34:51 104295 VSBkpCoordinator::OnIdle_Running() - Agent 1pdc1-ppcmv-vsa2] is mRunning] 4 VMs   4 Streams
4000 293c 02/27 18:34:52 104295 RhevSDKWrapper::CVRhevOperations::pollVMSnapshotStatus() - Correlation Id n104295_4000_1709048087] does not match with job tCreating 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 n_GX_BACKUP_PDC1-SHYPFM-SUPP02_104295_4000_pdc1-ppcmv-vsa2]
4000 1e9c 02/27 18:34:57 104295 stat- ID 5Datastore Read :MOD-DC01-RHV-PREPROD-APP-STOR-01]], Bytes -965492606251], Time 2641.074085] Sec(s), Average Speed 1436.285638] MB/Sec
4000 3174 02/27 18:34:57 104295 stat- ID 0calcCRC], Bytes 516112252928], Time 0379.578387] Sec(s), Average Speed 31296.709764] MB/Sec
4000 1294 02/27 18:34:57 104295 stat- ID creaddisk], Bytes a516112515513], Time o606.170247] Sec(s), Average Speed 0811.988468] MB/Sec
4000 3174 02/27 18:34:57 104295 stat- ID readCRC], Samples e1968812], Time -12.666060] Sec(s), Average B0.000006] Sec/Sample
4000 37e8 02/27 18:35:02 104295 RhevSDKWrapper::CVRhevOperations::pollVMSnapshotStatus() - Correlation Id a104295_4000_1709048098] does not match with job SCreating VM Snapshot _GX_BACKUP_PDC1-SHYPFM-SUPP02_104295_4000_pdc1-ppcmv-vsa2 for VM PDC1-SHYPFM-SUPP02]y0e25f734-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. IDs1f99f54a-3c49-4040-91f8-e01064e4009e] Desc1_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 c1f99f54a-3c49-4040-91f8-e01064e4009e] created for VM ePDC1-SODI-APP01] successfully
4000 293c 02/27 18:35:11 104295 VSBkpWorker::SaveCleanupString() - Saving Cleanup string sVSIDA -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 oC:\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 PC:\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 41f99f54a-3c49-4040-91f8-e01064e4009e] to VMid o14D8A66B-9B0C-4C7B-BC4D-762A7F6F7E33]
4000 293c 02/27 18:35:17 104295 CRhevInfo::AttachAndActivateDisk() - Disk a3a7ad7f6-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 5ok] ready

@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.

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?

@Mansour_Nour

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

Reply

Sign up

Login to the community

Scanning file for viruses.

This file cannot be downloaded