Solved

Error restoring DDB Store files. Restore job(s) [] encountered one or more errors.

  • 28 October 2021
  • 4 replies
  • 964 views

Badge +7


@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
Machine : <commserve>
File    : AuxCopyMgr.log
@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@

22900 46dc  10/28 16:51:58 4124325 DBBase-SQL() - dbmethods.cpp:1519, DB Layer will use [Exec] access by default. Use SetAdminAccess API for on demand Admin access.
22900 46dc  10/28 16:51:59 4124325 Cvcl::init() - CVCL: Running in FIPS Mode
22900 46dc  10/28 16:51:59 4124325 DetectNativeClient() - Found reg key [SOFTWARE\Microsoft\Microsoft SQL Server\SQLNCLI11]. Using driver [SQL Server Native Client 11.0].
22900 46dc  10/28 16:52:00 4124325 Starting DDB Recon with Indexed restore
22900 46dc  10/28 16:52:00 4124325 TaskInterfaceDB::getOptions() - Loading default options into memory
22900 46dc  10/28 16:52:00 4124325 Init() - Initializing job control [token=4124325:1:1,cn=<commserve>], serverName [<CS fqdn>], ControlFlag [1], Job Id [4124325]
22900 46dc  10/28 16:52:02 4124325 CVJobCtrlLog::registerProcess(): successfully created file [E:\Program Files\Commvault\ContentStore\Base\JobControl\22.900]
22900 46dc  10/28 16:52:02 4124325 AuxCopyManager::RestoreDDBStoreFiles Job option: DDB Reconstruction job in Restore Phase.
22900 46dc  10/28 16:52:02 4124325 AuxCopyManager::RestoreDDBStoreFiles Job option: Source Dedup Store ID [7].
22900 46dc  10/28 16:52:02 4124325 AuxCopyManager::RestoreDDBStoreFiles Job option: Full Reconstruction = [no].
22900 46dc  10/28 16:52:02 4124325 AuxCopyManager::RestoreDDBStoreFiles Job option : Corrupted Substore Id [24].
22900 46dc  10/28 16:52:02 4124325 isCCSDbEnabled() - Use CCSDb Enabled [0] IsCloudLaptop [0] IsFSCoreLaptop [0]
22900 46dc  10/28 16:52:02 4124325 GetIsUsingNewDownload() - Use New Download key is set to [true]
22900 46dc  10/28 16:52:02 4124325 AuxCopyManager::RestoreDDBStoreFiles Set Recovery mode for substore [24].
22900 46dc  10/28 16:52:02 4124325 [4] Sub stores with [4] groups configured for engine [7]
22900 46dc  10/28 16:52:02 4124325 SubstoRoutngInfo: EngId[7] (GrNo-SubStoId-SpltNo) 0-9-0 => 0-9-0 Clnt=[hq_media_svr4] Path=[D:\GDP_PROD_ARCHIVE] Status=[0]
22900 46dc  10/28 16:52:02 4124325 SubstoRoutngInfo: EngId[7] (GrNo-SubStoId-SpltNo) 1-24-1 => 0-9-0 Clnt=[hq_media_svr4] Path=[D:\GDP_PROD_ARCHIVE] Status=[1]
22900 46dc  10/28 16:52:02 4124325 SubstoRoutngInfo: EngId[7] (GrNo-SubStoId-SpltNo) 2-30-2 => 2-30-2 Clnt=[hq_media_svr4] Path=[D:\Dedupe_New\DDB_ARCHIVE5] Status=[0]
22900 46dc  10/28 16:52:02 4124325 SubstoRoutngInfo: EngId[7] (GrNo-SubStoId-SpltNo) 3-31-3 => 3-31-3 Clnt=[hq_media_svr4] Path=[D:\Dedupe_New\SSD_GDP_ARCHIVE] Status=[0]
22900 46dc  10/28 16:52:02 4124325 SubStore [24], Num [1] in recovery mode
22900 46dc  10/28 16:52:02 4124325 Connect: Connecting to Engine [7], Group [1], Client [<MA name>], Host [<IP and port>], Recovery Mode [true]
22900 46dc  10/28 16:52:03 4124325 Connected to Engine [7], Group [1], Socket [0x0000000000000548], Desc [<MA conenction details>(SIDB_<ddb name.) SIDB2.exe(16048:4514)], Address Family [IPv4], Local IP [127.0.0.1], Local Port [59351], Peer IP [127.0.0.1], Peer Port [49194]
22900 46dc  10/28 16:52:03 4124325 Disabling nagle on ddb connection.
22900 46dc  10/28 16:52:03 4124325 Socket buffer size [65536]
22900 46dc  10/28 16:52:03 4124325 SetRecoveryPhase: Phase [1000] for Group [1] completed successfully.
22900 46dc  10/28 16:52:03 4124325 AuxCopyManager::RestoreDDBStoreFiles Started a thread for restore DDB Substore ID [24], Store Id [7].
22900 6df0  10/28 16:52:03 4124325 RestoreDDBSubStore Going to restore DDB files for DDB Store [7], SubStore [24], Store Version [4].
22900 6df0  10/28 16:52:03 4124325 RestoreDDBSubStore No DDB Restore job is in progress for Store [7], Sub Store [24]
22900 6df0  10/28 16:52:04 4124325 RestoreDDBSubStore DDB Media Agent [hq_media_svr3] is at Release [0(BUILD80)], Build [0(BUILD80)], Service Pack []. Proceeding with reconstruction as it's not 9.0 SP3b.
22900 6df0  10/28 16:52:04 4124325 RestoreDDBSubStore Cannot delete corrupted DDB Store files for Store [7], SubStore [24], commCellId [2].
22900 46dc  10/28 16:52:33 4124325 AuxCopyManager::RestoreDDBStoreFiles DB_RECOVERY_CREATE_PHASE will not be set for any substores.
22900 46dc  10/28 16:52:33 4124325 AuxCopyManager::RestoreDDBStoreFiles Setting phase restart string to [-r SubStore_24;].
22900 46dc  10/28 16:52:33 4124325 COMPLETE CALLED (PHASE Status::FAIL), Job ID = 4124325
22900 46dc  10/28 16:52:34 4124325 [null] Stopping CVDAliveChecking
22900 46dc  10/28 16:52:34 4124325 CVJobCtrlLog::unregisterProcess(): successfully removed file [E:\Program Files\Commvault\ContentStore\Base\JobControl\22.900]

@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
Machine : <Commserve>
File    : JobManager.log
@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@

5396  5458  10/28 16:51:44 4124325             Servant    [---- SYSTEM INITIATED DEDUP DB RECONSTRUCTION REQUEST ----]. Task id [54115]
5396  5458  10/28 16:51:44 4124325             AuxCopyReserve::setChunksToSyncDDB archGroupCopyId [14] srcSIDBStoreId [7]
5396  5458  10/28 16:51:57 ################### DBBase-SQL() - dbcursors.cpp:311, Warning: Stored Procedure Procedure ArchChunkToSyncDDBInsert exceeded threshold time of 10, time taken: 13, Debug: [,4124325,14,7,1]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [1] : BytesToRead [175046023] FirstChunk [27654219]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [2] : BytesToRead [101976327] FirstChunk [27653543]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [3] : BytesToRead [7517034] FirstChunk [27655210]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [4] : BytesToRead [12243418942] FirstChunk [27665504]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [5] : BytesToRead [130243570] FirstChunk [27657332]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [6] : BytesToRead [176311311] FirstChunk [27654216]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [7] : BytesToRead [10693297] FirstChunk [27653544]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [8] : BytesToRead [47095380163] FirstChunk [27651467]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [9] : BytesToRead [114185337886] FirstChunk [27657325]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [10] : BytesToRead [3780658176] FirstChunk [27665508]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [11] : BytesToRead [22640240822] FirstChunk [27651466]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [12] : BytesToRead [4558493021] FirstChunk [27671300]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [13] : BytesToRead [439595101] FirstChunk [27672913]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [14] : BytesToRead [1449448671317] FirstChunk [27655206]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [15] : BytesToRead [24269545145] FirstChunk [27672727]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [16] : BytesToRead [1879513021] FirstChunk [27672818]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [17] : BytesToRead [8669668] FirstChunk [27657336]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [18] : BytesToRead [32444567452] FirstChunk [27651465]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [19] : BytesToRead [5669459203] FirstChunk [27658281]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [20] : BytesToRead [22679833909] FirstChunk [27651464]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [21] : BytesToRead [6663294441] FirstChunk [27659376]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [22] : BytesToRead [2693720446] FirstChunk [27672895]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [23] : BytesToRead [50539120] FirstChunk [27653549]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [24] : BytesToRead [3792345634] FirstChunk [27654860]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [25] : BytesToRead [287366346] FirstChunk [27655213]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [26] : BytesToRead [636756] FirstChunk [27655212]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [27] : BytesToRead [3341051] FirstChunk [27654869]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [28] : BytesToRead [353474] FirstChunk [27661540]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [29] : BytesToRead [2947917] FirstChunk [27654225]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [30] : BytesToRead [988091] FirstChunk [27654230]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [31] : BytesToRead [194752] FirstChunk [27654218]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [32] : BytesToRead [535759] FirstChunk [27655261]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [33] : BytesToRead [596165] FirstChunk [27655267]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [34] : BytesToRead [90115] FirstChunk [27655266]
5396  5458  10/28 16:51:57 4124325             AuxCopyReserve::getStreamsToSyncDDB Application Size, Source Copy [15] Stream [35] : BytesToRead [303286420] FirstChunk [27655273]
5396  61b0  10/28 16:51:58 4124325             Scheduler  Phase [1-Restore] (0,0) started on [<CS hostname>] in [0] second(s) - auxCopyMgr.exe -j 4124325 -t 54115 -a 14  -jt 4124325:1:1  -restore
5396  4854  10/28 16:52:02 4124325             Servant    Reg [Control] received. Client [<CS name>] plattype = 1. Token [4124325:1:1]
5396  68a8  10/28 16:52:34 4124325             Scheduler  Set pending cause [Error restoring DDB Store files. Restore job(s) [] encountered one or more errors.]::Client [<MA>] Application [AuxCopyMgr] Message Id [218103953] RCID [0] ReservationId [0].  Level [0] flags [0] id [0] overwrite [1] append [0] CustId[0].
5396  4854  10/28 16:52:34 4124325             Scheduler  Phase [Failed] message received from [<CS name>] Module [AuxCopyMgr] Token [4124325:1:1] restartPhase [0]
5396  4854  10/28 16:52:34 4124325             Scheduler  Phase succeeded partially. Retrying the phase.
5396  4854  10/28 16:52:34 4124325             JobSvr Obj Phase [1-Restore] for job Failed and will be restarted.
5396  4854  10/28 16:52:34 4124325             ArchiveMgr JMArMgr::releaseAllJobStreams() Calling CvResourceManager::releaseJobStreams(jobType=26,appType=1000,logicalRelease=true)

@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
Machine : <CS name>
File    : MediaManager.log
@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@

6312  2730  10/28 16:52:36 4124325 Connect: Connecting to Engine [7], Group [1], Client [<MA name>], Host [<MA connection details>], Recovery Mode [true]
6312  2730  10/28 16:52:39 4124325 Connected to Engine [7], Group [1], Socket [0x00000000000020BC], Desc [<MA connection details>(SIDB_<DDB name>) SIDB2.exe(19504:20c)], Address Family [IPv4], Local IP [127.0.0.1], Local Port [59464], Peer IP [127.0.0.1], Peer Port [49194]
6312  2730  10/28 16:52:39 ####### Disabling nagle on ddb connection.
6312  2730  10/28 16:52:39 ####### Socket buffer size [65536]
6312  2730  10/28 16:52:39 4124325 ControlPruning: Group [1] returned code [53042]
6312  2730  10/28 16:52:39 4124325  IDXSIDB  [       ]  Failed to Notify SIDB StoreID [7] Recon jobId [4124325] is in state [2], Ret [53042][The DDB is not in valid state for this operation]

@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
Machine : <CS name>
File    : ResourceManager.log
@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@

5396  4854  10/28 16:52:34 4124325 Resource   Releasing Stream Reader(s) for RCId [0]
 

icon

Best answer by Damian Andre 28 October 2021, 22:54

View original

4 replies

Userlevel 7
Badge +23

Hi @Alexzy , is this the same issue as your other thread?

 

Userlevel 7
Badge +23

When a DDB reconstruction is initiated, the contents of the folder containing the DDB are deleted. From the log file. the error getting (cannot delete corrupted DDB Store files for Store [7]) indicates a permissions issue on the folder but it can also be due to an open file at the OS level or AV issue or other environmental issue. Can you verify that these paths are accessible on the Media Agent hosting the DDB?

 

D:\GDP_PROD_ARCHIVE

D:\Dedupe_New\DDB_ARCHIVE5

D:\Dedupe_New\SSD_GDP_ARCHIVE


In such scenario, once we verified the access was OK we would would try to stop the commvault services on MA where DDB is located and rename the existing CV_SIDB folder to CV_SIDB.old and restart the service and then run the recon job - but I do not recommend that without engaging support, to absolutely verify the the correct DDB folder is renamed.

But your best bet here is to check the paths listed above and make sure they are accessible to the operating system and to Commvault.

Badge +7

thanks for ur quick respond, actually all D:\GDP_PROD_ARCHIVED:\Dedupe_New\DDB_ARCHIVE5D:\Dedupe_New\SSD_GDP_ARCHIVE

can be access.

what i notice was media server 3 cannot be reach from commserv him self, and for this reason Auxcopy is failing so far i hv restarted the media agent 3 and did full reconstruction to see if this can help.

Userlevel 7
Badge +23

Strange, perhaps there was a temporary glitch. I would not recommend full reconstruction as it can take a lot of time, but if its a small DDB it may not be so bad.

 

Reply