Solved

Problem with VM Live Sync replication

2 years ago
August 24, 2022
13 replies
1769 views

JuanPa
Bit
6 replies

I have the following error messages in the log

7244 f68 08/24 12:54:51 173589 [msg.dictionary.load.openFailed] Cannot open file "C:\ProgramData\VMware\VMware Virtual Disk Development Kit\config.ini": The system cannot find the file specified.

7244  f68   08/24 12:54:51 173589 lib/ssl: protocol list tls1.2 (openssl flags 0x17000000)
7244  f68   08/24 12:54:51 173589 lib/ssl: cipher list ECDHE+AESGCM:RSA+AESGCM:ECDHE+AES:RSA+AES
7244  f68   08/24 12:54:51 173589 lib/ssl: curves list prime256v1:secp384r1:secp521r1
7244  f68   08/24 12:54:51 173589 FILE: FileCreateDirectoryRetry: Non-retriable error encountered (C:\ProgramData\VMware): Cannot create a file when that file already exists (183)
7244  f68   08/24 12:54:51 173589 FILE: FileCreateDirectoryRetry: Non-retriable error encountered (C:\ProgramData\VMware): Cannot create a file when that file already exists (183)
7244  f68   08/24 12:54:51 173589 FILE: FileCreateDirectoryRetry: Non-retriable error encountered (C:\ProgramData\VMware): Cannot create a file when that file already exists (183)
7244  f68   08/24 12:54:51 173589 FILE: FileCreateDirectoryRetry: Non-retriable error encountered (C:\ProgramData\VMware): Cannot create a file when that file already exists (183)
7244  f68   08/24 12:54:51 173589 FILE: FileCreateDirectoryRetry: Non-retriable error encountered (C:\ProgramData\VMware): Cannot create a file when that file already exists (183)
7244  f68   08/24 12:54:51 173589

Best answer by Jos Meijer

Today I had time again to check the media agent install.
Issue definitely was in the Client object for this Media Agent.

Reinstalled Media Agent with new Client object, reconfigured DDB, Disklibrary, Tape Library and VSA relations for VM Live Sync.

Commserve also had issues, all sockets were in use.
Removed non-needed TPPM configurations and DIP's, rebooted Commserve.
Socket issue is gone, normal amount of sockets in use.

Tested DDB backup, Aux to disk and tape, VM replication, all works for this media agent.

Juan Pablo and I agree that this call can be closed @Mike Struening 👍

View original

Did this answer your question?

+17

Jos Meijer
Commvault Certified Expert
638 replies
2 years ago
August 24, 2022

These seem to be default "error" messages which are generated by the vddk. Which are common vsa log entries. Not expecting these messages to cause an error in a VM live sync process.

Can you describe the issue your experiencing with VM live sync?

JuanPa
Author
Bit
6 replies
2 years ago
August 25, 2022

I am experiencing problems when it starts to restore the VMs, sending the following:

File : vsrst.log
@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@

8684 2550 08/25 14:12:05 173736 = VSRST has started vsrst -j 173736 -cn commvault-drp -vm Instance001
8684 2550 08/25 14:12:05 173736 ================================================================
8684 2550 08/25 14:12:05 173736 CVMDiskInfo::GetVDDKInstallPath() - Using vStorage VDDK from [C:\Program Files\Commvault\ContentStore\Base\VMware\VDDK\VDDK673] version [6.7.3 build-14389676]
8684 2550 08/25 14:12:05 173736 CVMDiskInfo::LoadVDDKLibrary() - Successfully loaded VDDK Lib (libeay32.dll) from C:\Program Files\Commvault\ContentStore\Base\VMware\VDDK\VDDK673\bin\libeay32.dll
8684 2550 08/25 14:12:05 173736 CVMDiskInfo::LoadVDDKLibrary() - Successfully loaded VDDK Lib (ssleay32.dll) from C:\Program Files\Commvault\ContentStore\Base\VMware\VDDK\VDDK673\bin\ssleay32.dll
8684 2550 08/25 14:12:05 173736 CVMDiskInfo::LoadVDDKLibrary() - Successfully loaded VDDK Lib (libldap_r.dll) from C:\Program Files\Commvault\ContentStore\Base\VMware\VDDK\VDDK673\bin\libldap_r.dll
8684 2550 08/25 14:12:05 173736 CVMDiskInfo::LoadVDDKLibrary() - Successfully loaded VDDK Lib (libcurl.dll) from C:\Program Files\Commvault\ContentStore\Base\VMware\VDDK\VDDK673\bin\libcurl.dll
8684 2550 08/25 14:12:05 173736 VSRstApp::Initialize() - Initializing Job manager object
8684 1780 08/25 14:12:05 173736 CVDTerminationHandler::_WaitForCVDTermination() - Waiting for CVD Termination
8684 2550 08/25 14:12:06 173736 Cvcl::init() - CVCL: Running in FIPS Mode
8684 2550 08/25 14:12:06 173736 vsJobMgr::LoadJobOptions() - Job Options: <?xml version='1.0' encoding='utf-8' ?><TMMsg_JobOption><backupOpts backupLevel="2"><dataOpt autoCopy="0"/></backupOpts><adminOpts><contentIndexingOption subClientBasedAnalytics="0"/></adminOpts><restoreOptions><virtualServerRstOption isVolumeBrowse="0" isVirtualLab="0" esxServer="" isAttachToNewVM="0" isBlockLevelReplication="0" isDiskBrowse="1" viewType="0" replicationGuid="d5734afd-21a6-481c-b008-14ec429ec141" isFileBrowse="0"><vCenterInstance clientId="287" clientName="VCSADRP" instanceName="VMware" appName="Virtual Server" instanceId="20" applicationId="106"/><diskLevelVMRestoreOption passUnconditionalOverride="0" vcloudHostName="" hostOrCluster="" useVcloudCredentials="0" diskOption="2" powerOnVmAfterRestore="0" esxServerName="vcsadrp.da.shf.gob.mx" transportMode="0" maxNumOfVMPerJob="0"><userPassword userName="commvaultdrp@vsphere.local"/><advancedRestoreOptions esxHost="vmw-esx-drp-03.da.shf.gob.mx" resourcePoolPath="/" destComputerName="" FolderPath="/DC-DRP/vm/DRP_SHF/Replicas" newName="VM10-SAGAPL-DRP" Datastore="TrueNAS03" name="VM10-SAGAPL" guid="50102547-15b7-de98-7241-87a67323f581"><disks Datastore="TrueNAS03" name="scsi0-0-VM10-SAGAPL.vmdk"/><disks Datastore="TrueNAS03" name="scsi0-1-VM10-SAGAPL_1.vmdk"/><nics subnetId="" sourceNetwork="DSPGV82usr_82 (DSVMS)" sourceNetworkId="dvportgroup-1635" networkName="" destinationNetwork="VLAN708"/><vmIPAddressOptions destinationIP="10.10.82.45" destinationSubnet="255.255.255.128" alternateDNS="192.168.105.183" primaryWins="" alternateWins="" sourceSubnet="255.255.255.128" sourceIP="10.10.82.45" sourceGateway="10.10.82.126" primaryDNS="192.168.105.245" destinationGateway="10.10.82.126" useDhcp="0"/></advancedRestoreOptions><defaultRestoreSettings cluster="" esxHost="" protectionGroup="" resourcePoolPath="" datacenter="" DestinationPath="" Datastore=""/></diskLevelVMRestoreOption><allocationPolicy vmAllocPolicyId="0"/></virtualServerRstOption><volumeRstOption volumeLeveRestore="0" volumeLevelRestoreType="1" destinationVendor="1"/><browseOption listMedia="0" useExactIndex="0" noImage="0" commCellId="2" showDeletedItems="1"><mediaOption useISCSIMount="0"><mediaAgent mediaAgentId="0" _type_="11"/><library _type_="9" libraryId="0"/><copyPrecedence copyPrecedence="0" copyPrecedenceApplicable="0"/><drivePool _type_="47" drivePoolId="0"/></mediaOption><backupset instanceName="VMware" backupsetId="99" clientId="217" applicationId="106"/><timeZone _type_="55" TimeZoneID="24" TimeZoneName="(UTC-06:00) Guadalajara, Mexico City, Monterrey"/><timeRange/></browseOption><commonOptions systemStateBackup="0" clusterDBBackedup="0" powerRestore="0" restoreToDisk="0" copyToObjectStore="0" onePassRestore="0" syncRestore="0" detectRegularExpression="1" wildCard="0"/><destination inPlace="0"><destClient clientId="40"/></destination><fileOption><sourceItem val="\50102547-15b7-de98-7241-87a67323f581"/><browseFilters val="<?xml version='1.0' encoding='UTF-8'?><databrowse_Query type="0" queryId="0" />"/><browseFilters val="<?xml version='1.0' encoding='UTF-8'?><databrowse_Query type="0" queryId="0" />"/><browseFilters val="<?xml version='1.0' encoding='UTF-8'?><databrowse_Query type="0" queryId="0" />"/></fileOption></restoreOptions><commonOpts><automaticSchedulePattern useStorageSpaceFromMA="0"/></commonOpts><vmBrowsePathNodes esxHost="vmw-esx-drp-03.da.shf.gob.mx" datastore="TrueNAS03" vcloudVappName="" vmEsxHost="vmw-esx-drp-03.da.shf.gob.mx" vmInventoryPath="/DC-DRP/vm/DRP_SHF/Replicas" vmDataStore="TrueNAS03" isMetadataAvaiable="1" folder="" vcloudOrgVdcName="" vcloudOwner="" vmeResourcePoolPath="/" resourcePoolPath="/" DisplayName="VM10-SAGAPL" diskType="0" vcloudOrgName="" vmGUID="50102547-15b7-de98-7241-87a67323f581" browsePath="VM10-SAGAPL" isDriveNode="1"><nics subnetId="" sourceNetwork="DSPGV82usr_82 (DSVMS)" sourceNetworkId="dvportgroup-1635" networkName="" destinationNetwork="VLAN708"/></vmBrowsePathNodes><vmBrowsePathNodes esxHost="" datastore="" vcloudVappName="" vmEsxHost="" vmInventoryPath="" vmDataStore="" isMetadataAvaiable="1" folder="" vcloudOrgVdcName="" vcloudOwner="" vmeResourcePoolPath="" resourcePoolPath="" DisplayName="catalog" diskType="0" vcloudOrgName="" vmGUID="50102547-15b7-de98-7241-87a67323f581" browsePath="VM10-SAGAPL\catalog" isDriveNode="0"/><vmBrowsePathNodes esxHost="" datastore="" vcloudVappName="" vmEsxHost="" vmInventoryPath="" vmDataStore="" isMetadataAvaiable="1" folder="" vcloudOrgVdcName="" vcloudOwner="" vmeResourcePoolPath="" resourcePoolPath="" DisplayName="VM10-SAGAPL.nvram" diskType="0" vcloudOrgName="" vmGUID="50102547-15b7-de98-7241-87a67323f581" browsePath="VM10-SAGAPL\VM10-SAGAPL.nvram" isDriveNode="0"/><vmBrowsePathNodes esxHost="" datastore="TrueNAS03" vcloudVappName="" vmEsxHost="" vmInventoryPath="" vmDataStore="TrueNAS03" isMetadataAvaiable="1" folder="" vcloudOrgVdcName="" vcloudOwner="" vmeResourcePoolPath="" resourcePoolPath="" DisplayName="VM10-SAGAPL.vmdk" diskType="18" vcloudOrgName="" vmGUID="50102547-15b7-de98-7241-87a67323f581" browsePath="VM10-SAGAPL\scsi0-0-VM10-SAGAPL.vmdk" isDriveNode="0"/><vmBrowsePathNodes esxHost="" datastore="" vcloudVappName="" vmEsxHost="" vmInventoryPath="" vmDataStore="" isMetadataAvaiable="1" folder="" vcloudOrgVdcName="" vcloudOwner="" vmeResourcePoolPath="" resourcePoolPath="" DisplayName="VM10-SAGAPL.vmx" diskType="0" vcloudOrgName="" vmGUID="50102547-15b7-de98-7241-87a67323f581" browsePath="VM10-SAGAPL\VM10-SAGAPL.vmx" isDriveNode="0"/><vmBrowsePathNodes esxHost="" datastore="" vcloudVappName="" vmEsxHost="" vmInventoryPath="" vmDataStore="" isMetadataAvaiable="1" folder="" vcloudOrgVdcName="" vcloudOwner="" vmeResourcePoolPath="" resourcePoolPath="" DisplayName="VM10-SAGAPL.vmxf" diskType="0" vcloudOrgName="" vmGUID="50102547-15b7-de98-7241-87a67323f581" browsePath="VM10-SAGAPL\VM10-SAGAPL.vmxf" isDriveNode="0"/><vmBrowsePathNodes esxHost="" datastore="TrueNAS03" vcloudVappName="" vmEsxHost="" vmInventoryPath="" vmDataStore="TrueNAS03" isMetadataAvaiable="1" folder="" vcloudOrgVdcName="" vcloudOwner="" vmeResourcePoolPath="" resourcePoolPath="" DisplayName="VM10-SAGAPL_1.vmdk" diskType="18" vcloudOrgName="" vmGUID="50102547-15b7-de98-7241-87a67323f581" browsePath="VM10-SAGAPL\scsi0-1-VM10-SAGAPL_1.vmdk" isDriveNode="0"/><vmBrowsePathNodes esxHost="" datastore="" vcloudVappName="" vmEsxHost="" vmInventoryPath="" vmDataStore="" isMetadataAvaiable="1" folder="" vcloudOrgVdcName="" vcloudOwner="" vmeResourcePoolPath="" resourcePoolPath="" DisplayName="vmware-1.log" diskType="0" vcloudOrgName="" vmGUID="50102547-15b7-de98-7241-87a67323f581" browsePath="VM10-SAGAPL\vmware-1.log" isDriveNode="0"/><vmBrowsePathNodes esxHost="" datastore="" vcloudVappName="" vmEsxHost="" vmInventoryPath="" vmDataStore="" isMetadataAvaiable="1" folder="" vcloudOrgVdcName="" vcloudOwner="" vmeResourcePoolPath="" resourcePoolPath="" DisplayName="vmware-2.log" diskType="0" vcloudOrgName="" vmGUID="50102547-15b7-de98-7241-87a67323f581" browsePath="VM10-SAGAPL\vmware-2.log" isDriveNode="0"/><vmBrowsePathNodes esxHost="" datastore="" vcloudVappName="" vmEsxHost="" vmInventoryPath="" vmDataStore="" isMetadataAvaiable="1" folder="" vcloudOrgVdcName="" vcloudOwner="" vmeResourcePoolPath="" resourcePoolPath="" DisplayName="vmware-3.log" diskType="0" vcloudOrgName="" vmGUID="50102547-15b7-de98-7241-87a67323f581" browsePath="VM10-SAGAPL\vmware-3.log" isDriveNode="0"/><vmBrowsePathNodes esxHost="" datastore="" vcloudVappName="" vmEsxHost="" vmInventoryPath="" vmDataStore="" isMetadataAvaiable="1" folder="" vcloudOrgVdcName="" vcloudOwner="" vmeResourcePoolPath="" resourcePoolPath="" DisplayName="vmware.log" diskType="0" vcloudOrgName="" vmGUID="50102547-15b7-de98-7241-87a67323f581" browsePath="VM10-SAGAPL\vmware.log" isDriveNode="0"/></TMMsg_JobOption>
8684 2550 08/25 14:12:06 173736 Init() - Initializing job control [token=,cn=commvault-drp], serverName [commvault-drp.da.shf.gob.mx], ControlFlag [1], Job Id [173736]
8684 2550 08/25 14:12:06 173736 JM Client () - Failed to attach to remote service on retry 1. We will try again after some time
8684 2550 08/25 14:12:36 173736 CVJobCtrlClient::startSession()() - Failed to start a session with CVD. SessionError[150995030]::Error String[Internal Error [150994957] in CVSession while communicating with remote host [Remote system []. Required parameter missing [Remote client name].]. []], timedOut[FALSE]
8684 2550 08/25 14:12:36 173736 Init() - Error registering JOB with the Communications Service for JobID [173736]
8684 2550 08/25 14:12:36 173736 SetupConnectionWithCVD() - SetupConnectionWithCVD failed. mangledHostName= localClientName=commvault-drp TimeOut=False, error=0x80070057:{CCvNetwork::Attach_RemoteService(1692)} + {CCvNetwork::Attach_RemoteService(1655)} + {CCvNetwork::LookupRegisteredPorts(4700)} + {CCvNetwork::LookupRegisteredPorts_Common(4773)} + {CCvNetwork::DemangleHostNameToComps(4846)/W32.87.(The parameter is incorrect. (ERROR_INVALID_PARAMETER.87))-Invalid mangled host name:[] passed. Please use mangled host name.}
8684 2550 08/25 14:12:36 173736 SendToCVD() - Couldn't setup the connection
8684 2550 08/25 14:12:36 173736 Init() - registerJob failed. Returning failure
8684 2550 08/25 14:12:36 173736 vsJobMgr::init() - Failed to initialize job controller. CSName[ commvault-drp.da.shf.gob.mx], jobId [173736], JobMgrToken []
8684 2550 08/25 14:12:36 173736 VSRstApp::Initialize() - Job manager initialization failed
8684 1780 08/25 14:12:36 173736 CVDTerminationHandler::_WaitForCVDAliveMutex() - CVD Alive Check Quit Event Signaled
8684 2550 08/25 14:12:36 173736 = VSRst has exited
8684 2550 08/25 14:12:36 173736 ================================================================
8684 1fec 08/25 14:12:36 173736 JM Client () - Failed to attach to remote service on retry 1. We will try again after some time
8684 1fec 08/25 14:13:06 173736 CVJobCtrlClient::startSession()() - Failed to start a session with CVD. SessionError[150995030]::Error String[Internal Error [150994957] in CVSession while communicating with remote host [Remote system []. Required parameter missing [Remote client name].]. []], timedOut[FALSE]
8684 1fec 08/25 14:13:06 173736 controlThread() - Failed to unregister job with the Communications Service for JobID [173736]

+17

Jos Meijer
Commvault Certified Expert
638 replies
2 years ago
August 25, 2022

Here lies your issue:

8684 2550 08/25 14:12:36 173736 SetupConnectionWithCVD() - SetupConnectionWithCVD failed. mangledHostName= localClientName=commvault-drp TimeOut=False, error=0x80070057:{CCvNetwork::Attach_RemoteService(1692)} + {CCvNetwork::Attach_RemoteService(1655)} + {CCvNetwork::LookupRegisteredPorts(4700)} + {CCvNetwork::LookupRegisteredPorts_Common(4773)} + {CCvNetwork::DemangleHostNameToComps(4846)/W32.87.(The parameter is incorrect. (ERROR_INVALID_PARAMETER.87))-Invalid mangled host name:[] passed. Please use mangled host name.}

Have seen this multiple times on different versions, need to look back what the solution was. Not sure if this was DNS resolving or a Commvault internal issue.

Which Commvault version are you using?

Is this a newly installed VSA?

Can you share CVD.log? Curious if you have an anti chatter log entry.

+17

Jos Meijer
Commvault Certified Expert
638 replies
2 years ago
August 25, 2022

How is this VSA installation performed? Manually? If so did you use an XML file for the parameters? If not manually, via Push install or automation?

Reason for asking is, after reviewing support calls and taking another look at the log section, there is no mangled hostname provided. This could indicate that there was invalid information provided during the installation or a problem with the Commvault installation on this server.

A manual workaround in some old support cases was to manually edit registry by changing AntiChatterFlag to 0 and edit CsClientName with shortname and cycling the Commvault services on the client.

Some support cases also show a hotfix dependency, curious which Commvault version you are using.

JuanPa
Author
Bit
6 replies
2 years ago
August 25, 2022

It is a media Agent already in use, it has been working for several years, it was recently updated to SP24.60, but before the update it already had the problem.I share the log.

6280 74c 08/25 15:46:36 ###### TPool [SdtHeadThPool]. Tot [0], Pend [0], Comp [0], Max Par [0], Avg Work Time [0.00 s], Avg Wait Time [0.00 s]
6280 dd0 08/25 15:46:37 ------ CCVDSpaceCheck::CleanupIdleEventConnections() - Invoking CleanUp Idle Event Connections.
6280 f24 08/25 15:46:37 ###### GetRootFolders() - AllUsersProfileDirectory - [C:\ProgramData]
6280 72c 08/25 15:46:37 ###### IndexCacheCleanUpV2: Starting index cache cleanup thread
6280 72c 08/25 15:46:37 ###### getMyHostName_SpaceCheck() - ERROR: cannot determine mangled hostname for 'commvault-drp'
6280 72c 08/25 15:46:37 ###### IndexCacheCleanUpV2: failed to submit task. err [0xECCC0016:{CVOnDemandSvcClient::SubmitTask(43)/ErrNo.22.(Invalid argument)-mangled hostname and/or application name is empty}]
6280 72c 08/25 15:46:37 ------ launchCleanupService() - Failed to attach to CVD(IDXMessageHandler) on []
6280 72c 08/25 15:46:37 ------ IndexCacheMaintenance() - Regular cleanup skipped or failed: 0x80070057:{CCvNetwork::Attach_RemoteDLL(1419)} + {CCvNetwork::DemangleHostNameToComps(4846)/W32.87.(The parameter is incorrect. (ERROR_INVALID_PARAMETER.87))-Invalid mangled host name:[] passed. Please use mangled host name.}
6280 72c 08/25 15:46:37 ------ IndexCacheMaintenance() - Index cache for client [commvault-drp] is using 126786 MB. Location is [F:\Index].
6280 f58 08/25 15:46:38 ###### CCVIOMonitorLib::MonitorThreadStatic(568) - Total time spent in Anomaly detection: 0.001963
6280 f58 08/25 15:46:38 ###### CCVIOMonitorLib::MonitorThreadStatic(569) - Time spent in Anomaly detection algorithm: 0.000000
6280 584 08/25 15:46:55 173730 2-# [FSRESTHEAD ] Stats: AppTy 106, AF 2, Seeks 0/2/6, WrkItms 7, MsgsRcvd 21, QLen 13, LstMsg CLOSE_ARCHIVE_AND_REL_VOL
6280 584 08/25 15:46:55 173730 2-# [FSRESTHEAD ] Stats: [AllocBuf Time] Exp Avg [0.00], Total Avg [0.00], Total Time [0.00], Total Count [52]
6280 584 08/25 15:46:55 173730 2-# [FSRESTHEAD ] Stats: [AllocBuf Speed] Curr Avg [24399.13] MB/Sec, Bytes [3405792]; Total Avg [24399.13] MB/Sec, Bytes [3405792]
6280 584 08/25 15:46:55 173730 2-# [FSRESTHEAD ] Stats: [MediaRead Time] Exp Avg [0.00], Total Avg [0.00], Total Time [0.00], Total Count [52]
6280 584 08/25 15:46:55 173730 2-# [FSRESTHEAD ] Stats: [MediaRead Speed] Curr Avg [189.47] MB/Sec, Bytes [612909]; Total Avg [189.47] MB/Sec, Bytes [612909]
6280 584 08/25 15:46:55 ###### [FSRESTHEAD ] CSSrv::ChkState: Clnt [commvault-shf], JobId [0], Rdr has not progressed.
6280 21a8 08/25 15:46:57 ###### CFolderIOInfoWriter::PruneRecordsOlderThan(161) - Pruning successful, ClientId=[40], PruneTime=[2022/07/26 20:46:57.139327Z (1658868417)]
6280 21a8 08/25 15:46:57 ###### CFolderLevelIOInfoWriter::PruneRecordsOlderThan(681) - Pruning successful, ClientId=[40], PruneTime=[2022/08/18 20:46:57.139327Z (1660855617)]
6280 18e4 08/25 15:48:14 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 15:48:14 173730 1-# [DM_BASE ] Setting the job state to running
6280 18e4 08/25 15:48:14 173730 1-# [DM_BASE ] Going to retry the Restore Mount.
6280 18e4 08/25 15:48:16 173730 1-# [DM_BASE ] **ERROR** reserveMountVol Failed VolumeId = 29833 MA hostName- commvault-drp.da.shf.gob.mxClientName - commvault-drp MediaManager returned error [803], errorString [The medium is already reserved by some other job[s].]
6280 18e4 08/25 15:48:16 173730 1-# [DM_BASE ] Going to check whether the mount should be retried for the above mediamanager error
6280 18e4 08/25 15:48:16 173730 1-# [DM_BASE ] The mount will be retried for the MediaManager error [803] after sleeping for [120] seconds.
6280 18e4 08/25 15:48:16 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 15:48:16 173730 1-# [DM_BASE ] Setting the job state to waiting
6280 18e4 08/25 15:50:16 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 15:50:16 173730 1-# [DM_BASE ] Setting the job state to running
6280 18e4 08/25 15:50:16 173730 1-# [DM_BASE ] Going to retry the Restore Mount.
6280 18e4 08/25 15:50:18 173730 1-# [DM_BASE ] **ERROR** reserveMountVol Failed VolumeId = 29833 MA hostName- commvault-drp.da.shf.gob.mxClientName - commvault-drp MediaManager returned error [803], errorString [The medium is already reserved by some other job[s].]
6280 18e4 08/25 15:50:18 173730 1-# [DM_BASE ] Going to check whether the mount should be retried for the above mediamanager error
6280 18e4 08/25 15:50:18 173730 1-# [DM_BASE ] The mount will be retried for the MediaManager error [803] after sleeping for [120] seconds.
6280 18e4 08/25 15:50:18 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 15:50:18 173730 1-# [DM_BASE ] Setting the job state to waiting
6280 74c 08/25 15:51:36 ###### TPool [CVDMessageHandler]. Ser# [0] Tot [1], Pend [0], Comp [1], Max Par [1], Avg Work Time [327.21 us], Avg Wait Time [101.93 us]
6280 74c 08/25 15:51:36 ###### TPool [CVDMessageHandler]. Ser# [1] Tot [7], Pend [1], Comp [6], Max Par [4], Avg Work Time [199.79 ms], Avg Wait Time [1.54 ms]
6280 74c 08/25 15:51:36 ###### TPool [IOCPServerPool_JobControlCVD]. Ser# [1] Tot [28], Pend [28], Comp [0], Max Par [0], Avg Work Time [0.00 s], Avg Wait Time [0.00 s]
6280 74c 08/25 15:51:36 ###### TPool [IOCPServerPool_CVD]. Ser# [1] Tot [28], Pend [28], Comp [0], Max Par [0], Avg Work Time [0.00 s], Avg Wait Time [0.00 s]
6280 74c 08/25 15:51:36 ###### TPool [CVD]. Ser# [0] Tot [1], Pend [0], Comp [1], Max Par [1], Avg Work Time [31.19 us], Avg Wait Time [85.64 us]
6280 74c 08/25 15:51:36 ###### TPool [CVD]. Ser# [1] Tot [1], Pend [0], Comp [1], Max Par [1], Avg Work Time [256.47 us], Avg Wait Time [50.27 us]
6280 74c 08/25 15:51:36 ###### TPool [IOCPServerPool_SysMonEventSink]. Ser# [1] Tot [28], Pend [28], Comp [0], Max Par [0], Avg Work Time [0.00 s], Avg Wait Time [0.00 s]
6280 74c 08/25 15:51:36 ###### TPool [SdtHeadThPool]. Tot [0], Pend [0], Comp [0], Max Par [0], Avg Work Time [0.00 s], Avg Wait Time [0.00 s]
6280 72c 08/25 15:51:37 ###### GetRootFolders() - AllUsersProfileDirectory - [C:\ProgramData]
6280 f58 08/25 15:51:38 ###### CCVIOMonitorLib::MonitorThreadStatic(568) - Total time spent in Anomaly detection: 0.002399
6280 f58 08/25 15:51:38 ###### CCVIOMonitorLib::MonitorThreadStatic(569) - Time spent in Anomaly detection algorithm: 0.000000
6280 21a8 08/25 15:51:57 ###### CFolderIOInfoWriter::PruneRecordsOlderThan(161) - Pruning successful, ClientId=[40], PruneTime=[2022/07/26 20:51:57.254812Z (1658868717)]
6280 21a8 08/25 15:51:57 ###### CFolderLevelIOInfoWriter::PruneRecordsOlderThan(681) - Pruning successful, ClientId=[40], PruneTime=[2022/08/18 20:51:57.254812Z (1660855917)]
6280 18e4 08/25 15:52:18 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 15:52:18 173730 1-# [DM_BASE ] Setting the job state to running
6280 18e4 08/25 15:52:18 173730 1-# [DM_BASE ] Going to retry the Restore Mount.
6280 18e4 08/25 15:52:20 173730 1-# [DM_BASE ] **ERROR** reserveMountVol Failed VolumeId = 29833 MA hostName- commvault-drp.da.shf.gob.mxClientName - commvault-drp MediaManager returned error [803], errorString [The medium is already reserved by some other job[s].]
6280 18e4 08/25 15:52:20 173730 1-# [DM_BASE ] Going to check whether the mount should be retried for the above mediamanager error
6280 18e4 08/25 15:52:20 173730 1-# [DM_BASE ] The mount will be retried for the MediaManager error [803] after sleeping for [120] seconds.
6280 18e4 08/25 15:52:20 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 15:52:20 173730 1-# [DM_BASE ] Setting the job state to waiting
6280 18e4 08/25 15:54:20 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 15:54:20 173730 1-# [DM_BASE ] Setting the job state to running
6280 18e4 08/25 15:54:20 173730 1-# [DM_BASE ] Going to retry the Restore Mount.
6280 18e4 08/25 15:54:22 173730 1-# [DM_BASE ] **ERROR** reserveMountVol Failed VolumeId = 29833 MA hostName- commvault-drp.da.shf.gob.mxClientName - commvault-drp MediaManager returned error [803], errorString [The medium is already reserved by some other job[s].]
6280 18e4 08/25 15:54:22 173730 1-# [DM_BASE ] Going to check whether the mount should be retried for the above mediamanager error
6280 18e4 08/25 15:54:22 173730 1-# [DM_BASE ] The mount will be retried for the MediaManager error [803] after sleeping for [120] seconds.
6280 18e4 08/25 15:54:22 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 15:54:22 173730 1-# [DM_BASE ] Setting the job state to waiting
6280 18e4 08/25 15:56:22 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 15:56:22 173730 1-# [DM_BASE ] Setting the job state to running
6280 18e4 08/25 15:56:22 173730 1-# [DM_BASE ] Going to retry the Restore Mount.
6280 18e4 08/25 15:56:24 173730 1-# [DM_BASE ] **ERROR** reserveMountVol Failed VolumeId = 29833 MA hostName- commvault-drp.da.shf.gob.mxClientName - commvault-drp MediaManager returned error [803], errorString [The medium is already reserved by some other job[s].]
6280 18e4 08/25 15:56:24 173730 1-# [DM_BASE ] Going to check whether the mount should be retried for the above mediamanager error
6280 18e4 08/25 15:56:24 173730 1-# [DM_BASE ] The mount will be retried for the MediaManager error [803] after sleeping for [120] seconds.
6280 18e4 08/25 15:56:24 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 15:56:24 173730 1-# [DM_BASE ] Setting the job state to waiting
6280 270 08/25 15:56:36 ------ CvSearchEngineOperation::TaggerThread() - Search engine is not installed. Nothing to do.
6280 72c 08/25 15:56:36 ###### CvSearchTask::populateAllNicIpaddressToCS() - Client [COMMVAULT-DRP] ipAddress is [192.168.105.64,::1,]
6280 72c 08/25 15:56:36 ------ CvSearchTask::CVEnableAnalyticsAccessControl() - Analytics package is not Installed.
6280 72c 08/25 15:56:36 ###### CvSearchTask::CVSyncContentAnalyzerInfo() - In function CVSyncContentAnalyzerInfo.
6280 72c 08/25 15:56:36 ------ CvSearchTask::CVSyncContentAnalyzerInfo() - Content Analyzer package is not Installed.
6280 74c 08/25 15:56:36 ###### TPool [CVDMessageHandler]. Ser# [1] Tot [8], Pend [0], Comp [8], Max Par [3], Avg Work Time [134.84 ms], Avg Wait Time [502.58 us]
6280 74c 08/25 15:56:36 ###### TPool [IOCPServerPool_JobControlCVD]. Ser# [1] Tot [28], Pend [28], Comp [0], Max Par [0], Avg Work Time [0.00 s], Avg Wait Time [0.00 s]
6280 74c 08/25 15:56:36 ###### TPool [IOCPServerPool_CVD]. Ser# [1] Tot [28], Pend [28], Comp [0], Max Par [0], Avg Work Time [0.00 s], Avg Wait Time [0.00 s]
6280 74c 08/25 15:56:36 ###### TPool [IOCPServerPool_SysMonEventSink]. Ser# [1] Tot [28], Pend [28], Comp [0], Max Par [0], Avg Work Time [0.00 s], Avg Wait Time [0.00 s]
6280 74c 08/25 15:56:36 ###### TPool [SdtHeadThPool]. Tot [0], Pend [0], Comp [0], Max Par [0], Avg Work Time [0.00 s], Avg Wait Time [0.00 s]
6280 72c 08/25 15:56:37 ###### GetRootFolders() - AllUsersProfileDirectory - [C:\ProgramData]
6280 1894 08/25 15:56:37 ###### CVClientPerformanceHistory::sendFileToCS() - Request to send file:[1661460997_PerfLog_System-1.2_14719194173747207366.csv] from source location:[C:\Program Files\Commvault\ContentStore\Base\Temp] to destination directory:[C:\Program Files\Commvault\ContentStore\Base\Temp\ResourceMonitor\40] on Commserver.
6280 1894 08/25 15:56:37 ###### CVClientPerformanceHistory::sendFileToCS() - Sent file [1661460997_PerfLog_System-1.2_14719194173747207366.csv] to Commserver
6280 f58 08/25 15:56:38 ###### CCVIOMonitorLib::MonitorThreadStatic(568) - Total time spent in Anomaly detection: 0.002013
6280 f58 08/25 15:56:38 ###### CCVIOMonitorLib::MonitorThreadStatic(569) - Time spent in Anomaly detection algorithm: 0.000000
6280 584 08/25 15:56:55 173730 2-# [FSRESTHEAD ] Stats: AppTy 106, AF 2, Seeks 0/2/6, WrkItms 7, MsgsRcvd 21, QLen 13, LstMsg CLOSE_ARCHIVE_AND_REL_VOL
6280 584 08/25 15:56:55 173730 2-# [FSRESTHEAD ] Stats: [AllocBuf Time] Exp Avg [0.00], Total Avg [0.00], Total Time [0.00], Total Count [52]
6280 584 08/25 15:56:55 173730 2-# [FSRESTHEAD ] Stats: [AllocBuf Speed] Curr Avg [24399.13] MB/Sec, Bytes [3405792]; Total Avg [24399.13] MB/Sec, Bytes [3405792]
6280 584 08/25 15:56:55 173730 2-# [FSRESTHEAD ] Stats: [MediaRead Time] Exp Avg [0.00], Total Avg [0.00], Total Time [0.00], Total Count [52]
6280 584 08/25 15:56:55 173730 2-# [FSRESTHEAD ] Stats: [MediaRead Speed] Curr Avg [189.47] MB/Sec, Bytes [612909]; Total Avg [189.47] MB/Sec, Bytes [612909]
6280 584 08/25 15:56:55 ###### [FSRESTHEAD ] CSSrv::ChkState: Clnt [commvault-shf], JobId [0], Rdr has not progressed.
6280 21a8 08/25 15:56:57 ###### CFolderIOInfoWriter::PruneRecordsOlderThan(161) - Pruning successful, ClientId=[40], PruneTime=[2022/07/26 20:56:57.333767Z (1658869017)]
6280 21a8 08/25 15:56:57 ###### CFolderLevelIOInfoWriter::PruneRecordsOlderThan(681) - Pruning successful, ClientId=[40], PruneTime=[2022/08/18 20:56:57.333767Z (1660856217)]
6280 18e4 08/25 15:58:24 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 15:58:24 173730 1-# [DM_BASE ] Setting the job state to running
6280 18e4 08/25 15:58:24 173730 1-# [DM_BASE ] Going to retry the Restore Mount.
6280 18e4 08/25 15:58:27 173730 1-# [DM_BASE ] **ERROR** reserveMountVol Failed VolumeId = 29833 MA hostName- commvault-drp.da.shf.gob.mxClientName - commvault-drp MediaManager returned error [803], errorString [The medium is already reserved by some other job[s].]
6280 18e4 08/25 15:58:27 173730 1-# [DM_BASE ] Going to check whether the mount should be retried for the above mediamanager error
6280 18e4 08/25 15:58:27 173730 1-# [DM_BASE ] The mount will be retried for the MediaManager error [803] after sleeping for [120] seconds.
6280 18e4 08/25 15:58:27 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 15:58:27 173730 1-# [DM_BASE ] Setting the job state to waiting
6280 270 08/25 16:00:15 ###### CvProcess::StartProcessUnicode() - Preparing to launch process: <C:\Program Files\Commvault\ContentStore\Base\ifind.exe>. Priority: <Normal>. Value: <32> creational flag <8>.
6280 270 08/25 16:00:15 ###### [CVD ] Remote Command Request from remotehost = <10.10.165.221>, RemoteClient = <commvault-shf>, RemoteIP(Sock) = <10.10.165.221>. Launched Process: <ifind.exe -j 173753 -a 2:47 -t 1 -d commvault-drp.da.shf.gob.mx*commvault-drp*8400 -r 1661374811 -ab 0 -i 1 -cs commvault-shf -s "DDBBackup" -jt 173753:4:1:0:38472 -systemFiles -mountPath -seb -lf 173606 -li 0 -ls 0 -attrEx 0 -cn commvault-drp -vm Instance001>. Pid=6728
6280 18e4 08/25 16:00:27 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 16:00:27 173730 1-# [DM_BASE ] Setting the job state to running
6280 18e4 08/25 16:00:27 173730 1-# [DM_BASE ] Going to retry the Restore Mount.
6280 270 08/25 16:00:30 ###### [CVD ] Submitting thread start request to launch service for App: [cvjobreplicatorods]
6280 1424 08/25 16:00:30 ###### [CVD ] Launching CVODS.exe, Args [-svcname CVODS_cvjobreplicatorods_commvault-drp_1 -appname CVJobReplicatorODS ] on [commvault-drp.da.shf.gob.mx*commvault-drp*8400]
6280 270 08/25 16:00:30 ###### CvProcess::StartProcessUnicode() - Preparing to launch process: <C:\Program Files\Commvault\ContentStore\Base\CVODS.exe>. Priority: <Normal>. Value: <32> creational flag <8>.
6280 270 08/25 16:00:30 ###### [CVD ] Remote Command Request from remotehost = <commvault-drp.da.shf.gob.mx>, RemoteClient = <commvault-drp>, RemoteIP(Sock) = <127.0.0.1>. Launched Process: <CVODS.exe -svcname CVODS_cvjobreplicatorods_commvault-drp_1 -appname CVJobReplicatorODS -cn commvault-drp cvshost:commvault-drp.da.shf.gob.mx*commvault-drp cvsport:50728:0 cvsmyplatform:2 cvsremoteplatform:4 -vm Instance001>. Pid=6984
6280 18e4 08/25 16:00:30 173730 1-# [DM_BASE ] **ERROR** reserveMountVol Failed VolumeId = 29833 MA hostName- commvault-drp.da.shf.gob.mxClientName - commvault-drp MediaManager returned error [803], errorString [The medium is already reserved by some other job[s].]
6280 18e4 08/25 16:00:30 173730 1-# [DM_BASE ] Going to check whether the mount should be retried for the above mediamanager error
6280 18e4 08/25 16:00:30 173730 1-# [DM_BASE ] The mount will be retried for the MediaManager error [803] after sleeping for [120] seconds.
6280 18e4 08/25 16:00:30 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 16:00:30 173730 1-# [DM_BASE ] Setting the job state to waiting
6280 1424 08/25 16:00:30 ###### [CVD ] Successfully launched on demand service [CVODS_cvjobreplicatorods_commvault-drp_1] and submitted job request, Unique id is [89070181-16F2-4099-992E-36F1A305210A]
6280 74c 08/25 16:01:36 ###### TPool [CVDMessageHandler]. Ser# [0] Tot [6], Pend [0], Comp [6], Max Par [1], Avg Work Time [110.34 ms], Avg Wait Time [80.29 us]
6280 74c 08/25 16:01:36 ###### TPool [CVDMessageHandler]. Ser# [1] Tot [7], Pend [0], Comp [7], Max Par [3], Avg Work Time [17.98 ms], Avg Wait Time [903.91 us]
6280 74c 08/25 16:01:36 ###### TPool [IOCPServerPool_JobControlCVD]. Ser# [1] Tot [28], Pend [28], Comp [0], Max Par [0], Avg Work Time [0.00 s], Avg Wait Time [0.00 s]
6280 74c 08/25 16:01:36 ###### TPool [IOCPServerPool_CVD]. Ser# [1] Tot [28], Pend [28], Comp [0], Max Par [0], Avg Work Time [0.00 s], Avg Wait Time [0.00 s]
6280 74c 08/25 16:01:36 ###### TPool [CVD]. Ser# [0] Tot [3], Pend [0], Comp [3], Max Par [1], Avg Work Time [29.32 us], Avg Wait Time [82.23 us]
6280 74c 08/25 16:01:36 ###### TPool [CVD]. Ser# [1] Tot [3], Pend [0], Comp [3], Max Par [1], Avg Work Time [31.19 us], Avg Wait Time [83.47 us]
6280 74c 08/25 16:01:36 ###### TPool [IOCPServerPool_SysMonEventSink]. Ser# [1] Tot [28], Pend [28], Comp [0], Max Par [0], Avg Work Time [0.00 s], Avg Wait Time [0.00 s]
6280 74c 08/25 16:01:36 ###### TPool [cvjobreplicatorods]. Ser# [0] Tot [1], Pend [0], Comp [1], Max Par [1], Avg Work Time [772.49 ms], Avg Wait Time [1.79 ms]
6280 74c 08/25 16:01:36 ###### TPool [SdtHeadThPool]. Tot [0], Pend [0], Comp [0], Max Par [0], Avg Work Time [0.00 s], Avg Wait Time [0.00 s]
6280 270 08/25 16:01:37 ###### GetRootFolders() - AllUsersProfileDirectory - [C:\ProgramData]
6280 f58 08/25 16:01:38 ###### CCVIOMonitorLib::MonitorThreadStatic(568) - Total time spent in Anomaly detection: 0.002090
6280 f58 08/25 16:01:38 ###### CCVIOMonitorLib::MonitorThreadStatic(569) - Time spent in Anomaly detection algorithm: 0.000000
6280 21a8 08/25 16:02:00 ###### CFolderIOInfoWriter::PruneRecordsOlderThan(161) - Pruning successful, ClientId=[40], PruneTime=[2022/07/26 21:02:00.574082Z (1658869320)]
6280 21a8 08/25 16:02:00 ###### CFolderLevelIOInfoWriter::PruneRecordsOlderThan(681) - Pruning successful, ClientId=[40], PruneTime=[2022/08/18 21:02:00.574082Z (1660856520)]
6280 18e4 08/25 16:02:30 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 16:02:30 173730 1-# [DM_BASE ] Setting the job state to running
6280 18e4 08/25 16:02:30 173730 1-# [DM_BASE ] Going to retry the Restore Mount.
6280 18e4 08/25 16:02:32 173730 1-# [DM_BASE ] **ERROR** reserveMountVol Failed VolumeId = 29833 MA hostName- commvault-drp.da.shf.gob.mxClientName - commvault-drp MediaManager returned error [803], errorString [The medium is already reserved by some other job[s].]
6280 18e4 08/25 16:02:32 173730 1-# [DM_BASE ] Going to check whether the mount should be retried for the above mediamanager error
6280 18e4 08/25 16:02:32 173730 1-# [DM_BASE ] The mount will be retried for the MediaManager error [803] after sleeping for [120] seconds.
6280 18e4 08/25 16:02:32 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 16:02:32 173730 1-# [DM_BASE ] Setting the job state to waiting
6280 270 08/25 16:04:08 ###### CvProcess::StartProcessUnicode() - Preparing to launch process: <C:\Program Files\Commvault\ContentStore\Base\vsrst.exe>. Priority: <Normal>. Value: <32> creational flag <8>.
6280 270 08/25 16:04:08 ###### [CVD ] Remote Command Request from remotehost = <commvault-shf.da.shf.gob.mx>, RemoteClient = <commvault-shf>, RemoteIP(Sock) = <10.10.165.221>. Launched Process: <vsrst -j 173734 -cn commvault-drp -vm Instance001>. Pid=2980
6280 18e4 08/25 16:04:32 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 16:04:32 173730 1-# [DM_BASE ] Setting the job state to running
6280 18e4 08/25 16:04:32 173730 1-# [DM_BASE ] Going to retry the Restore Mount.
6280 18e4 08/25 16:04:34 173730 1-# [DM_BASE ] **ERROR** reserveMountVol Failed VolumeId = 29833 MA hostName- commvault-drp.da.shf.gob.mxClientName - commvault-drp MediaManager returned error [803], errorString [The medium is already reserved by some other job[s].]
6280 18e4 08/25 16:04:34 173730 1-# [DM_BASE ] Going to check whether the mount should be retried for the above mediamanager error
6280 18e4 08/25 16:04:34 173730 1-# [DM_BASE ] The mount will be retried for the MediaManager error [803] after sleeping for [120] seconds.
6280 18e4 08/25 16:04:34 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 16:04:34 173730 1-# [DM_BASE ] Setting the job state to waiting
6280 18e4 08/25 16:06:34 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 16:06:34 173730 1-# [DM_BASE ] Setting the job state to running
6280 18e4 08/25 16:06:34 173730 1-# [DM_BASE ] Going to retry the Restore Mount.
6280 74c 08/25 16:06:36 ###### TPool [CVDMessageHandler]. Ser# [0] Tot [2], Pend [0], Comp [2], Max Par [1], Avg Work Time [2.91 ms], Avg Wait Time [96.12 us]
6280 74c 08/25 16:06:36 ###### TPool [CVDMessageHandler]. Ser# [1] Tot [7], Pend [1], Comp [6], Max Par [2], Avg Work Time [9.51 ms], Avg Wait Time [818.35 us]
6280 74c 08/25 16:06:36 ###### TPool [IOCPServerPool_JobControlCVD]. Ser# [1] Tot [28], Pend [28], Comp [0], Max Par [0], Avg Work Time [0.00 s], Avg Wait Time [0.00 s]
6280 74c 08/25 16:06:36 ###### TPool [IOCPServerPool_CVD]. Ser# [1] Tot [28], Pend [28], Comp [0], Max Par [0], Avg Work Time [0.00 s], Avg Wait Time [0.00 s]
6280 74c 08/25 16:06:36 ###### TPool [CVD]. Ser# [0] Tot [1], Pend [0], Comp [1], Max Par [1], Avg Work Time [32.58 us], Avg Wait Time [85.18 us]
6280 74c 08/25 16:06:36 ###### TPool [CVD]. Ser# [1] Tot [1], Pend [0], Comp [1], Max Par [1], Avg Work Time [37.70 us], Avg Wait Time [46.55 us]
6280 74c 08/25 16:06:36 ###### TPool [IOCPServerPool_SysMonEventSink]. Ser# [1] Tot [28], Pend [28], Comp [0], Max Par [0], Avg Work Time [0.00 s], Avg Wait Time [0.00 s]
6280 74c 08/25 16:06:36 ###### TPool [SdtHeadThPool]. Tot [0], Pend [0], Comp [0], Max Par [0], Avg Work Time [0.00 s], Avg Wait Time [0.00 s]
6280 18e4 08/25 16:06:36 173730 1-# [DM_BASE ] **ERROR** reserveMountVol Failed VolumeId = 29833 MA hostName- commvault-drp.da.shf.gob.mxClientName - commvault-drp MediaManager returned error [803], errorString [The medium is already reserved by some other job[s].]
6280 18e4 08/25 16:06:36 173730 1-# [DM_BASE ] Going to check whether the mount should be retried for the above mediamanager error
6280 18e4 08/25 16:06:36 173730 1-# [DM_BASE ] The mount will be retried for the MediaManager error [803] after sleeping for [120] seconds.
6280 18e4 08/25 16:06:36 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 16:06:36 173730 1-# [DM_BASE ] Setting the job state to waiting
6280 1894 08/25 16:06:37 ###### IndexCacheCleanUpV2: Starting index cache cleanup thread
6280 1894 08/25 16:06:37 ###### getMyHostName_SpaceCheck() - ERROR: cannot determine mangled hostname for 'commvault-drp'
6280 1894 08/25 16:06:37 ###### IndexCacheCleanUpV2: failed to submit task. err [0xECCC0016:{CVOnDemandSvcClient::SubmitTask(43)/ErrNo.22.(Invalid argument)-mangled hostname and/or application name is empty}]
6280 1894 08/25 16:06:37 ------ launchCleanupService() - Failed to attach to CVD(IDXMessageHandler) on []
6280 1894 08/25 16:06:37 ------ IndexCacheMaintenance() - Regular cleanup skipped or failed: 0x80070057:{CCvNetwork::Attach_RemoteDLL(1419)} + {CCvNetwork::DemangleHostNameToComps(4846)/W32.87.(The parameter is incorrect. (ERROR_INVALID_PARAMETER.87))-Invalid mangled host name:[] passed. Please use mangled host name.}
6280 1894 08/25 16:06:37 ------ IndexCacheMaintenance() - Index cache for client [commvault-drp] is using 126786 MB. Location is [F:\Index].
6280 270 08/25 16:06:37 ###### GetRootFolders() - AllUsersProfileDirectory - [C:\ProgramData]
6280 1f68 08/25 16:06:37 ------ CCVDSpaceCheck::CleanupIdleEventConnections() - Invoking CleanUp Idle Event Connections.
6280 f58 08/25 16:06:38 ###### CCVIOMonitorLib::MonitorThreadStatic(568) - Total time spent in Anomaly detection: 0.001942
6280 f58 08/25 16:06:38 ###### CCVIOMonitorLib::MonitorThreadStatic(569) - Time spent in Anomaly detection algorithm: 0.000000
6280 584 08/25 16:06:55 173730 2-# [FSRESTHEAD ] Stats: AppTy 106, AF 2, Seeks 0/2/7, WrkItms 7, MsgsRcvd 24, QLen 16, LstMsg SEEK_TO_OFFSET
6280 584 08/25 16:06:55 173730 2-# [FSRESTHEAD ] Stats: [CtrlCh Idle Time] Exp Avg [0.04], Total Avg [0.04], Total Time [0.18], Total Count [5]
6280 584 08/25 16:06:55 173730 2-# [FSRESTHEAD ] Stats: [Seek Time] Exp Avg [301.05], Total Avg [301.05], Total Time [602.10], Total Count [2]
6280 584 08/25 16:06:55 173730 2-# [FSRESTHEAD ] Stats: [AllocBuf Time] Exp Avg [0.00], Total Avg [0.00], Total Time [0.00], Total Count [52]
6280 584 08/25 16:06:55 173730 2-# [FSRESTHEAD ] Stats: [AllocBuf Speed] Curr Avg [24399.13] MB/Sec, Bytes [3405792]; Total Avg [24399.13] MB/Sec, Bytes [3405792]
6280 584 08/25 16:06:55 173730 2-# [FSRESTHEAD ] Stats: [MediaRead Time] Exp Avg [0.00], Total Avg [0.00], Total Time [0.00], Total Count [52]
6280 584 08/25 16:06:55 173730 2-# [FSRESTHEAD ] Stats: [MediaRead Speed] Curr Avg [189.47] MB/Sec, Bytes [612909]; Total Avg [189.47] MB/Sec, Bytes [612909]
6280 584 08/25 16:06:55 ###### [FSRESTHEAD ] CSSrv::ChkState: Clnt [commvault-shf], JobId [0], Rdr has not progressed.
6280 21a8 08/25 16:07:00 ###### CFolderIOInfoWriter::PruneRecordsOlderThan(161) - Pruning successful, ClientId=[40], PruneTime=[2022/07/26 21:07:00.660875Z (1658869620)]
6280 21a8 08/25 16:07:00 ###### CFolderLevelIOInfoWriter::PruneRecordsOlderThan(681) - Pruning successful, ClientId=[40], PruneTime=[2022/08/18 21:07:00.660875Z (1660856820)]
6280 18e4 08/25 16:08:36 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 16:08:36 173730 1-# [DM_BASE ] Setting the job state to running
6280 18e4 08/25 16:08:36 173730 1-# [DM_BASE ] Going to retry the Restore Mount.
6280 18e4 08/25 16:08:38 173730 1-# [DM_BASE ] **ERROR** reserveMountVol Failed VolumeId = 29833 MA hostName- commvault-drp.da.shf.gob.mxClientName - commvault-drp MediaManager returned error [803], errorString [The medium is already reserved by some other job[s].]
6280 18e4 08/25 16:08:38 173730 1-# [DM_BASE ] Going to check whether the mount should be retried for the above mediamanager error
6280 18e4 08/25 16:08:38 173730 1-# [DM_BASE ] The mount will be retried for the MediaManager error [803] after sleeping for [120] seconds.
6280 18e4 08/25 16:08:38 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 16:08:38 173730 1-# [DM_BASE ] Setting the job state to waiting
6280 18e4 08/25 16:10:38 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 16:10:38 173730 1-# [DM_BASE ] Setting the job state to running
6280 18e4 08/25 16:10:38 173730 1-# [DM_BASE ] Going to retry the Restore Mount.
6280 18e4 08/25 16:10:41 173730 1-# [DM_BASE ] **ERROR** reserveMountVol Failed VolumeId = 29833 MA hostName- commvault-drp.da.shf.gob.mxClientName - commvault-drp MediaManager returned error [803], errorString [The medium is already reserved by some other job[s].]
6280 18e4 08/25 16:10:41 173730 1-# [DM_BASE ] Going to check whether the mount should be retried for the above mediamanager error
6280 18e4 08/25 16:10:41 173730 1-# [DM_BASE ] The mount will be retried for the MediaManager error [803] after sleeping for [120] seconds.
6280 18e4 08/25 16:10:41 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 16:10:41 173730 1-# [DM_BASE ] Setting the job state to waiting
6280 74c 08/25 16:11:36 ###### TPool [CVDMessageHandler]. Ser# [1] Tot [7], Pend [0], Comp [7], Max Par [3], Avg Work Time [125.55 ms], Avg Wait Time [592.59 us]
6280 74c 08/25 16:11:36 ###### TPool [IOCPServerPool_JobControlCVD]. Ser# [1] Tot [28], Pend [28], Comp [0], Max Par [0], Avg Work Time [0.00 s], Avg Wait Time [0.00 s]
6280 74c 08/25 16:11:36 ###### TPool [IOCPServerPool_CVD]. Ser# [1] Tot [28], Pend [28], Comp [0], Max Par [0], Avg Work Time [0.00 s], Avg Wait Time [0.00 s]
6280 74c 08/25 16:11:36 ###### TPool [IOCPServerPool_SysMonEventSink]. Ser# [1] Tot [28], Pend [28], Comp [0], Max Par [0], Avg Work Time [0.00 s], Avg Wait Time [0.00 s]
6280 74c 08/25 16:11:36 ###### TPool [SdtHeadThPool]. Tot [0], Pend [0], Comp [0], Max Par [0], Avg Work Time [0.00 s], Avg Wait Time [0.00 s]
6280 410 08/25 16:11:37 ###### GetRootFolders() - AllUsersProfileDirectory - [C:\ProgramData]
6280 28bc 08/25 16:11:37 ###### CVClientPerformanceHistory::sendFileToCS() - Request to send file:[1661461897_PerfLog_System-1.2_14719194173747207366.csv] from source location:[C:\Program Files\Commvault\ContentStore\Base\Temp] to destination directory:[C:\Program Files\Commvault\ContentStore\Base\Temp\ResourceMonitor\40] on Commserver.
6280 28bc 08/25 16:11:37 ###### CVClientPerformanceHistory::sendFileToCS() - Sent file [1661461897_PerfLog_System-1.2_14719194173747207366.csv] to Commserver
6280 f58 08/25 16:11:38 ###### CCVIOMonitorLib::MonitorThreadStatic(568) - Total time spent in Anomaly detection: 0.002075
6280 f58 08/25 16:11:38 ###### CCVIOMonitorLib::MonitorThreadStatic(569) - Time spent in Anomaly detection algorithm: 0.000000
6280 21a8 08/25 16:12:01 ###### CFolderIOInfoWriter::PruneRecordsOlderThan(161) - Pruning successful, ClientId=[40], PruneTime=[2022/07/26 21:12:01.843901Z (1658869921)]
6280 21a8 08/25 16:12:01 ###### CFolderLevelIOInfoWriter::PruneRecordsOlderThan(681) - Pruning successful, ClientId=[40], PruneTime=[2022/08/18 21:12:01.843901Z (1660857121)]
6280 18e4 08/25 16:12:41 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 16:12:41 173730 1-# [DM_BASE ] Setting the job state to running
6280 18e4 08/25 16:12:41 173730 1-# [DM_BASE ] Going to retry the Restore Mount.
6280 18e4 08/25 16:12:43 173730 1-# [DM_BASE ] **ERROR** reserveMountVol Failed VolumeId = 29833 MA hostName- commvault-drp.da.shf.gob.mxClientName - commvault-drp MediaManager returned error [803], errorString [The medium is already reserved by some other job[s].]
6280 18e4 08/25 16:12:43 173730 1-# [DM_BASE ] Going to check whether the mount should be retried for the above mediamanager error
6280 18e4 08/25 16:12:43 173730 1-# [DM_BASE ] The mount will be retried for the MediaManager error [803] after sleeping for [120] seconds.
6280 18e4 08/25 16:12:43 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 16:12:43 173730 1-# [DM_BASE ] Setting the job state to waiting
6280 18e4 08/25 16:14:43 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 16:14:43 173730 1-# [DM_BASE ] Setting the job state to running
6280 18e4 08/25 16:14:43 173730 1-# [DM_BASE ] Going to retry the Restore Mount.
6280 18e4 08/25 16:14:45 173730 1-# [DM_BASE ] **ERROR** reserveMountVol Failed VolumeId = 29833 MA hostName- commvault-drp.da.shf.gob.mxClientName - commvault-drp MediaManager returned error [803], errorString [The medium is already reserved by some other job[s].]
6280 18e4 08/25 16:14:45 173730 1-# [DM_BASE ] Going to check whether the mount should be retried for the above mediamanager error
6280 18e4 08/25 16:14:45 173730 1-# [DM_BASE ] The mount will be retried for the MediaManager error [803] after sleeping for [120] seconds.
6280 18e4 08/25 16:14:45 173730 1-# [DM_BASE ] Setting the Job Id to the mounting job
6280 18e4 08/25 16:14:45 173730 1-# [DM_BASE ] Setting the job state to waiting

JuanPa
Author
Bit
6 replies
2 years ago
August 25, 2022

I share full log

1 Attachments

cvd.txt

+17

Jos Meijer
Commvault Certified Expert
638 replies
2 years ago
August 25, 2022

Can't remember seeing this issue on 11.24.60, I am fairly positive this is a install/registry related issue.

Would be easiest if I could take a look and discuss the issue via a remote session with you on the media agent. If you want to, send me details for a session via a message to my profile. I will be available for the next hour.

+17

Jos Meijer
Commvault Certified Expert
638 replies
2 years ago
August 26, 2022

Quick recap:

Performed a remote session, identified that there is a problem with the installation of instance001.
Keeps having issues with mangled hostname or service attachment, no matter what is corrected.

Validated that a secondary instance installation does work.
Communication and processes work as expected.

Juan Pablo is now looking at a reinstall of the commvault software for the damaged instance001.

+19

Onno van den Berg
Commvault Certified Expert
1232 replies
2 years ago
August 26, 2022

@Jos Meijer to the rescue!

+23

Mike Struening
Vaulter
4996 replies
2 years ago
August 26, 2022

You never cease to amaze me, @Jos Meijer !!

https://www.linkedin.com/in/michael-struening

+17

Jos Meijer
Commvault Certified Expert
638 replies
2 years ago
August 26, 2022

I try to help where I can. 🙃
But no celebration yet, reinstall seems to continue to have the same issue.
Need to check the install, but I am starting to wonder if the issue lies within the client object as a secondary instance test was working like a charm.

+23

Mike Struening
Vaulter
4996 replies
2 years ago
August 26, 2022

I’m still impressed!

I unmarked the answer until confirmed.

https://www.linkedin.com/in/michael-struening

+17

Jos Meijer
Commvault Certified Expert
638 replies
Answer
2 years ago
August 29, 2022

Today I had time again to check the media agent install.
Issue definitely was in the Client object for this Media Agent.

Reinstalled Media Agent with new Client object, reconfigured DDB, Disklibrary, Tape Library and VSA relations for VM Live Sync.

Commserve also had issues, all sockets were in use.
Removed non-needed TPPM configurations and DIP's, rebooted Commserve.
Socket issue is gone, normal amount of sockets in use.

Tested DDB backup, Aux to disk and tape, VM replication, all works for this media agent.

Juan Pablo and I agree that this call can be closed @Mike Struening 👍

Reply

Cookie policy

We use cookies to enhance and personalize your experience. If you accept you agree to our full cookie policy. Learn more about our cookies.

Cookie settings

We use 3 different kinds of cookies. You can choose which cookies you want to accept. We need basic cookies to make this site work, therefore these are the minimum you can select. Learn more about our cookies.

Basic
Functional

Normal
Functional + analytics

Complete
Functional + analytics + social media + embedded videos

1 Attachments

Reply

Related topics

Would you suggest how to view the ddb or storage policy name in command center for ddb verifications.icon

The best configuraion for Commvaul Immutable soluion in Azureicon

Would you suggest how to view the server or storage policy in command center for aux copy jobsicon

Plansicon

Commvault Official Deduplication Limits

Most helpful members this week

Sign up

Login to the community

Scanning file for viruses.

This file cannot be downloaded

Cookie policy

Cookie settings