Skip to main content
commvault.com commvault.com
Solved

File Archive stub restore not working on some files

  • November 14, 2022
  • 8 replies
  • 1231 views
R
Bit
Forum|alt.badge.img+4

Am helping on a site where we have Windows file archive in place where most stubs / complete files can be recovered fine with no issues, however there are a few stubs that simply wont recover correctly nd are just replaced as a stub instead of the original file.

 

Have tried the following:

  • select - restore data instead of stub
  • out of place recover direct to the windows Media Agent (bypass any client network issues)
  • out of place recover to Linux file system to rule out AV, windows domain file permissions (only stub was recovered, not complete file, ran job twice with restore data instead of stub...)
  • Cross Hardware restore option.
  • checked for any strange windows / domain file permissions - all seem good.
  • Full data verification on tape was run and completed 100%

busy running a new Aux copy to second tape and will test recall from that copy precedence. (only one copy is on tape.. not best practice, however I didn't set it up this way)

 

nothing much in the logs. I increase logging on the restore log too.

Running on FR11.20.30x

 

Any ideas, much appreciated.

 

Regards,

Rob

 

Best answer by RobsterFine

Hi Mike,

just thought I’d update this thread. We eventually managed to get Commvault support on this and they quickly found the problem. It took a while as we found out they were out of support and had to make arrangements to get things approved.

The original files were stubbed by another subclient years ago. Not sure exactly what happened and when things somehow got “ migrated”.

The restore logs were looking for data inside subclient “2239” 

Support ran the GXHSMUtility.exe -view “stub file location” on the file server.

in the output the line “SubclientID=2012”  showed the sub client we needed to browse for the first pass “backup”  

Regards,

Robert

 

 

View original
Robert Fine
Did this answer your question?

8 replies

Mike Struening
Vaulter
Forum|alt.badge.img+23

@RobsterFine , when you try and restore via the stub, does a restore job kick off (and just place the stub there), or does nothing really happen?

It almost sounds like the archiving job somehow stubbed a stub.

https://www.linkedin.com/in/michael-struening
R
Bit
Forum|alt.badge.img+4
  • RobsterFine
  • Author
  • Bit
  • 6 replies
  • November 15, 2022

Hi Mike,

thanks for responding,

The restore job kicks off - either persistent restore if we click on the stub in windows explorer or full restore job when restored from the GUI.

I’ll look back into earlier archiving jobs to see if this was a stub that somehow got “stubbed” again.

just noticed late yesterday something I missed when I looked at original logs. - out of 5 subs restored, 3 were not successful and logs say those files were “unavailable” - have highlighted in Red below.

will check older archive jobs too see if this somehow has not “stubbed a stub” in the past. 

 

Thanks, Regards,

Robert

 

@@@

Machine : Servername334

File    : clRestore.log

@@@

 

17104 31f4  11/09 11:54:20 9329233 CVArchive::FwdRstMsg() - Restore Head Msg Logging = [0]

17104 31f4  11/09 11:54:20 9329233 FclRestore::OnMsgOpenArchive() - Launching the readPipeline thread...

17104 478c  11/09 11:54:20 9329233 FclRestore::AFileReadTimeMonitor() - Starting

17104 31f4  11/09 11:54:20 9329233 FclRestore::OnMsgSeekToOffset10(11890) - Recieved seek array of size [7]

17104 31f4  11/09 11:54:20 9329233 FclRestore::OnMsgSeekToOffset10(11912) - Processing seek message (offset, flags, ver, path, linkname) [53557890183:0400:0:\D:\StubFiles\warrene1.pst:unavailable] (noticed this “unavailable” here.. all these failed)

17104 31f4  11/09 11:54:20 9329233 FclRestore::OnMsgSeekToOffset10(11912) - Processing seek message (offset, flags, ver, path, linkname) [53557904751:0400:0:\D:\StubFiles\warrene_archive.pst:unavailable]

17104 31f4  11/09 11:54:20 9329233 FclRestore::OnMsgSeekToOffset10(11912) - Processing seek message (offset, flags, ver, path, linkname) [1293816088318:0002:0:\D:\StubFiles\evanse.pst:\D:\StubFiles\evanse.pst]. (This stub restored as file successfully)

17104 31f4  11/09 11:54:20 9329233 FclRestore::OnMsgSeekToOffset10(11912) - Processing seek message (offset, flags, ver, path, linkname) [1574612789051:0002:0:\D:\StubFiles\AbramovA.pst:\D:\StubFiles\AbramovA.pst] (This stub restored as file successfully)

17104 31f4  11/09 11:54:20 9329233 FclRestore::OnMsgSeekToOffset10(11912) - Processing seek message (offset, flags, ver, path, linkname) [2725419116567:0400:0:\D:\StubFiles\AbramovA.pst:unavailable]

17104 31f4  11/09 11:54:20 9329233 FclRestore::OnMsgSeekToOffset10(11912) - Processing seek message (offset, flags, ver, path, linkname) [2725419141355:0000:0:\D:\StubFiles\AghaR.pst:unavailable]

17104 31f4  11/09 11:54:20 9329233 FclRestore::OnMsgSeekToOffset10(11912) - Processing seek message (offset, flags, ver, path, linkname) [2746130745644:0400:0:\D:\StubFiles\evanse.pst:unavailable]

17104 31f4  11/09 11:54:20 9329233 FClRestore::ProcessRestoreMessage() - Processing FSR_MSG_CLOSE_ARCHIVE

17104 31f4  11/09 11:54:20 9329233 FclRestore::OnMsgCloseArchive() - Waiting for readPipeline thread to exit...

17104 1868  11/09 11:54:21 9329233 SdtEncDec::processSetEncProps: [000000BB4AD05550] AfIds [9036470 ]

17104 1868  11/09 11:54:21 9329233 CArchFileKeys::Init() - Max Afile key map size set to 8192. Connection Count = 8

17104 3fac  11/09 11:54:21 9329233 CVArchive::ReadBuffer() - PL_SET_ENC_PROPS(2, 11, 9036470)

17104 2ee0  11/09 11:54:21 9329233 SdtBase::SetNwCrcProps: Enabled n/w crc on SdtTail. [Using slice-by-8] RCId [1]

17104 3fac  11/09 11:54:21 9329233 CVArchive::ReadBuffer() - PL_SET_NETWORK_CRC_PROPS (2, 11, 9036470)

17104 3fac  11/09 11:54:21 9329233 CVArchive::ReadBuffer() - PL_FS_OPEN_AFILE(2, 11, 9036470)

17104 36fc  11/09 11:55:47 9329233 FetchKeysByEncryptArgs() - Fetching Enc keys [1/1] for AFile 9036470, copyId 25

17104 36fc  11/09 11:55:47 9329233 FetchKeysByEncryptArgs() - Got 256-bit AES Enc. key for AFile 9036470, CopyId 25, flg 0, MapSiz 1

17104 3fac  11/09 11:55:47 9329233 FclRestore::ProcessPlFsHeader() - Current apptype [33]; Restoring file [D:\StubFiles\warrene1.pst]

17104 3fac  11/09 11:55:47 9329233 FsRestoreNTObjectsFactory::createRestoreObject() - version = 0 (0) (C:\temp\restore\test\warrene1.pst)

17104 3fac  11/09 11:55:47 9329233 FclRestore::ProcessIndexHdr() - Received index header for file D:\StubFiles\warrene1.pst

17104 3fac  11/09 11:55:47 9329233 FclRestore::ProcessPlFsHeader() - Current apptype [33]; Restoring file [D:\StubFiles\warrene_archive.pst]

17104 3fac  11/09 11:55:47 9329233 FsRestoreNTObjectsFactory::createRestoreObject() - version = 0 (0) (C:\temp\restore\test\warrene_archive.pst)

17104 3fac  11/09 11:55:47 9329233 FclRestore::ProcessIndexHdr() - Received index header for file D:\StubFiles\warrene_archive.pst

17104 3fac  11/09 11:55:47 9329233 FclRestore::OnBufferPlFsPreHdr(12921) - PrevLinkPath=[\D:\StubFiles\evanse.pst], CurrentLinkPath=[\D:\StubFiles\evanse.pst]

17104 3fac  11/09 11:55:47 9329233 FclRestore::ProcessPlFsHeader() - Current apptype [33]; Restoring file [D:\StubFiles\evanse.pst]

17104 3fac  11/09 11:55:47 9329233 FsRestoreNTObjectsFactory::createRestoreObject() - version = 0 (0) (C:\temp\restore\test\evanse.pst)

17104 3fac  11/09 11:55:47 9329233 FclRestore::ProcessIndexHdr() - Received index header for file D:\StubFiles\evanse.pst

17104 3fac  11/09 11:56:34 9329233 FclRestore::UpdateStatistics(14999) - C:\temp\restore\test\evanse.pst   [DATA]    [ Reason:      ]   -> 5

17104 3fac  11/09 11:56:34 9329233 FclRestore::OnBufferPlFsPreHdr(12921) - PrevLinkPath=[\D:\StubFiles\AbramovA.pst], CurrentLinkPath=[\D:\StubFiles\AbramovA.pst]

17104 3fac  11/09 11:56:34 9329233 FclRestore::ProcessPlFsHeader() - Current apptype [33]; Restoring file [D:\StubFiles\AbramovA.pst]

17104 3fac  11/09 11:56:34 9329233 FsRestoreNTObjectsFactory::createRestoreObject() - version = 0 (0) (C:\temp\restore\test\AbramovA.pst)

17104 3fac  11/09 11:56:34 9329233 FclRestore::ProcessIndexHdr() - Received index header for file D:\StubFiles\AbramovA.pst

17104 3fac  11/09 11:57:12 9329233 FclRestore::UpdateStatistics(14999) - C:\temp\restore\test\AbramovA.pst   [DATA]    [ Reason:      ]   -> 5

17104 3fac  11/09 11:57:12 9329233 FclRestore::ProcessPlFsHeader() - Current apptype [33]; Restoring file [D:\StubFiles\AbramovA.pst]

17104 3fac  11/09 11:57:12 9329233 FsRestoreNTObjectsFactory::createRestoreObject() - version = 0 (0) (C:\temp\restore\test\AbramovA.pst)

17104 3fac  11/09 11:57:12 9329233 IsFileGalaxyStub(2307): -Debug-: File C:\temp\restore\test\AbramovA.pst is not a STUB file.

17104 3fac  11/09 11:57:12 9329233 FclRestore::ProcessIndexHdr() - Received index header for file D:\StubFiles\AbramovA.pst

17104 3fac  11/09 11:57:12 9329233 FclRestore::ProcessPlFsHeader() - Current apptype [33]; Restoring file [D:\StubFiles\AghaR.pst]

17104 3fac  11/09 11:57:12 9329233 FsRestoreNTObjectsFactory::createRestoreObject() - version = 0 (0) (C:\temp\restore\test\AghaR.pst)

17104 3fac  11/09 11:57:12 9329233 FclRestore::ProcessIndexHdr() - Received index header for file D:\StubFiles\AghaR.pst

17104 3fac  11/09 11:58:07 9329233 FclRestore::UpdateStatistics(14999) - C:\temp\restore\test\AghaR.pst   [DATA]    [ Reason:      ]   -> 5

17104 3fac  11/09 11:58:07 9329233 FclRestore::ProcessPlFsHeader() - Current apptype [33]; Restoring file [D:\StubFiles\evanse.pst]

17104 3fac  11/09 11:58:07 9329233 FsRestoreNTObjectsFactory::createRestoreObject() - version = 0 (0) (C:\temp\restore\test\evanse.pst)

17104 3fac  11/09 11:58:07 9329233 IsFileGalaxyStub(2307): -Debug-: File C:\temp\restore\test\evanse.pst is not a STUB file.

17104 3fac  11/09 11:58:07 9329233 FclRestore::ProcessIndexHdr() - Received index header for file D:\StubFiles\evanse.pst

17104 3fac  11/09 11:58:07 9329233 CVArchive::ReadBuffer() - PL_PERF_COUNTERS (2, 11, 9036470)

17104 3fac  11/09 11:58:07 9329233 CVArchive::ReadBuffer() - PL_FS_CLOSE_AFILE(2, 11, 9036470)

17104 3fac  11/09 11:58:07 9329233 FclRestore::readPipeline() - Received PL_FS_CLOSE_AFILE buffer. Exiting thread...

17104 3fac  11/09 11:58:07 9329233 FclRestore::readPipeline() - Exiting the thread...

17104 3fac  11/09 11:58:07 9329233 FclRestore::readPipelineStatic() - Waiting on the archive file read monitor thread to stop

17104 478c  11/09 11:58:07 9329233 FclRestore::AFileReadTimeMonitor() - Stopping the Archive File Read Monitor Thread

17104 3fac  11/09 11:58:07 9329233 FclRestore::readPipelineStatic() - Archive file read monitor thread has stopped

17104 31f4  11/09 11:58:07 9329233 FClRestore::ProcessRestoreMessage() - Processing FSR_MSG_WAIT_ARCHIVE_CLOSED

17104 31f4  11/09 11:58:08 9329233 FClRestore::ProcessRestoreMessage() - Processing FSR_MSG_RESTORE_END

17104 31f4  11/09 11:58:08 9329233 FclRestore::OnMsgRestoreEnd() - Applying timestamps to the restored folders

17104 31f4  11/09 11:58:08 9329233 FclRestore::OnMsgRestoreEnd() - Successfully applied folder timestamps

17104 31f4  11/09 11:58:08 9329233 FclRestore::OnMsgRestoreEnd() - Restore params=[65720l]

17104 31f4  11/09 11:58:08 9329233 FclRestore::OnMsgRestoreEnd() - Restore on client [Servername334.customer01.internal] subclient [Fileserver01_PSTArchive] completed...

17104 31f4  11/09 11:58:08 9329233 FclRestore::OnMsgRestoreEnd() - File Statistics: Total [5], Succeeded [3], Skipped [0] Failed [0] Need Reboot [0]

17104 31f4  11/09 11:58:08 9329233 FclRestore::OnMsgRestoreEnd() - Byte Statistics: Total [3232861880], Succeeded [3232861880], Skipped [0] Failed [0]

17104 31f4  11/09 11:58:08 9329233 FclRestore::OnMsgRestoreEnd() - The failed byte count does not include files that failed due to seek error

17104 31f4  11/09 11:58:08 9329233 FclRestore::OnMsgRestoreEnd() - sending FSR_MSG_RESTORE_END to FSRestoreHead

17104 3af8  11/09 11:58:08 9329233 FclRestore::receiveRestoreMsgs() - Waking up after FSR_MSG_RESTORE_END has been processed

17104 3af8  11/09 11:58:08 9329233 FclRestore::ResumeRestoreMessageProcessor()() - Resuming restore msg processor

17104 31f4  11/09 11:58:08 9329233 JOBRESCACHEDIR: state is set to 0

 

 

 

 

Robert Fine
Mike Struening
Vaulter
Forum|alt.badge.img+23

That’s definitely the issue in red.  Now, what’s the cause?  Could be a few things.

Check the backup logs if possible, though I’d advise contacting support directly.

I’d want to know what happened, but also if any OTHER files are affected.

https://www.linkedin.com/in/michael-struening
R
Bit
Forum|alt.badge.img+4
  • RobsterFine
  • Author
  • Bit
  • 6 replies
  • November 15, 2022

Hi Mike,

I completely forgot to mention the job we are trying to restore from is a Synthetic Full on Tape (I’ve never setup or used Synth fulls on tape...)   

Plan is to now double check the previous incremental jobs.  Next would be older synth full / incremental to see if this file was first stubbed in one of those. Problem is these jobs were done many years ago so logs won't be around. Further challenge is the older tapes are apparently not available??? sigh… 

As for support, apparently was all renewed in March then them some complexities happened and no one told the backup team so they busy getting it resolved. 

I created a secondary copy - very strange that only one small job was automatically selected then had to do some digging to get more jobs to copy across. As Murphy's law goes on tape - the tape drive went off line during the copy for a bit and a chunk could not get read or copied… so only 400GB of the 4TB data was moved… sigh again.. (and previous data verification job was fine) 

Will solder on and let you know what happens. will have support on this as soon as we can.

it’s apparently only a very small number of files affected at this point, however these are needed for a legal review so quite important.

Regards,

Robert

 

Robert Fine
Mike Struening
Vaulter
Forum|alt.badge.img+23

Appreciate the background, and hopefully the support renewal is set (or set soon).

What I suspect is happening here (added context) is that you were using OnePass which is essentially a backup and an archive in one.

the first backup job backs up everything, as well as archives any files as per your parameters in the subclient properties.

The next jobs are Incrementals as expected.

However, from that point forward, you ONLY run Synth Fulls and no normal fulls.  This is to ensure that the archive piece rolls forward forever.

Otherwise, when the older jobs aged off, your stubs would be useless.

With that said, there’s a possibility some Inc failed or a Synth full had issues (pure speculation) which is why they are not working.

Only way to know for sure is for support to take a deeper dive.

Keep me posted!

https://www.linkedin.com/in/michael-struening
R
Bit
Forum|alt.badge.img+4
  • RobsterFine
  • Author
  • Bit
  • 6 replies
  • November 16, 2022

Hi Mike,

Yes, this looks like an older OnePass setup. (just never seen a synthetic full on tape before)

we’ve browsed as many jobs as we can to see when these files were first “backed up” and then stubbed. 

Seems it was back around 2017. We’ve tried restores from various Synthetic Fulls once we loaded the tapes again - all failed and just restored the stub. Noticed none of them reported in the logs that the file was “unavailable” as mentioned in previous post / log.

We’ve been trying to find the original incremental job that contains the file and not stub, however at the moment (unless we’ve missed it) - it does not exist (or been deleted?). 

 

out of interest - The error below is what happens if you use the Edge plugin to recover the stubbed file. 

280  46c   11/16 13:00:35 ####### NoPrefix initialized a new browse session [6AA83E21-0F6C-48D0-81C6-C43FDD4C8B46]
3280  46c   11/16 13:00:39 ####### NoPrefix session [6AA83E21-0F6C-48D0-81C6-C43FDD4C8B46] is terminated, it has been idle for [0] mins and idle timeout is [30] mins
3280  46c   11/16 13:00:39 ####### DMRRequest::SubmitInternal(1610) - Data cannot be retrieved, error=[0x8007065B:{DMRIndexLookup::LookUpIndexByDataGUID(354)/W32.1627.(Function failed during execution. (ERROR_FUNCTION_FAILED.1627))-No result returned from Index for 'GUID 74af983536b8cfaf3b4cc0ca0109fab5'}]
3280  46c   11/16 13:00:39 ####### SubmitRecallRequestToDMR(58) - Failed to submit recall request for file  : 'D:\StubFiles\warrene1.pst' Error :[49]
3280  46c   11/16 13:00:39 ####### CFSDMAPIRecallResponder::Respond(65) - Recall request failed for file D:\StubFiles\warrene1.pst with error:Skipping retrieval
3280  46c   11/16 13:00:39 ####### CFSDMAPIRecallResponder::Respond(156) - Retrying restore request

 

If there is a script of command I can run to find out when this file was originally backed up / stubbed that could help locate the missing job. The Incremental do show that files are there as “File” then later on in the synthetic full’s they are listed as Stubs. (of which most can be restored) 

 

Regards,

Robert

 

Robert Fine
Mike Struening
Vaulter
Forum|alt.badge.img+23

If there is a script, I’m not aware of it.  would be best to open a support case.

My assumption here is that for whatever reason, the recall in 2017 fails, and subsequent backups simply copied the stub itself (hence why it’s there but fails today).

Why it failed back then might be a mystery never solved, though a deeper dive via support is your best bet here.

Let me know the case number so I can track it.

https://www.linkedin.com/in/michael-struening
R
Bit
Forum|alt.badge.img+4
  • RobsterFine
  • Author
  • Bit
  • 6 replies
  • Answer
  • January 30, 2023

Hi Mike,

just thought I’d update this thread. We eventually managed to get Commvault support on this and they quickly found the problem. It took a while as we found out they were out of support and had to make arrangements to get things approved.

The original files were stubbed by another subclient years ago. Not sure exactly what happened and when things somehow got “ migrated”.

The restore logs were looking for data inside subclient “2239” 

Support ran the GXHSMUtility.exe -view “stub file location” on the file server.

in the output the line “SubclientID=2012”  showed the sub client we needed to browse for the first pass “backup”  

Regards,

Robert

 

 

Robert Fine

Reply


Most helpful members this week

Terms & ConditionsCookie settings

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