+3
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
Hi
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.
+3
Hi
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="<?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 [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="<?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 [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
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.
Enter your username or e-mail address. We'll send you an e-mail with instructions to reset your password.
