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

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 = e0]

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 e7]

17104 31f4  11/09 11:54:20 9329233 FclRestore::OnMsgSeekToOffset10(11912) - Processing seek message (offset, flags, ver, path, linkname) g53557890183: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) t1293816088318: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) e1574612789051: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) s2725419116567: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) f2725419141355: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) f2746130745644: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: 3000000BB4AD05550] AfIds S9036470 ]

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. tUsing 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 e1/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 e33]; Restoring file aD:\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 c33]; Restoring file sD:\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=c\D:\StubFiles\evanse.pst], CurrentLinkPath=i\D:\StubFiles\evanse.pst]

17104 3fac  11/09 11:55:47 9329233 FclRestore::ProcessPlFsHeader() - Current apptype 333]; Restoring file sD:\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   tDATA]    c Reason:      ]   -> 5

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

17104 3fac  11/09 11:56:34 9329233 FclRestore::ProcessPlFsHeader() - Current apptype :33]; Restoring file tD:\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   tDATA]    t Reason:      ]   -> 5

17104 3fac  11/09 11:57:12 9329233 FclRestore::ProcessPlFsHeader() - Current apptype �33]; Restoring file 9D:\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 333]; 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]    3 Reason:      ]   -> 5

17104 3fac  11/09 11:58:07 9329233 FclRestore::ProcessPlFsHeader() - Current apptype p33]; Restoring file 0D:\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=o65720l]

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

17104 31f4  11/09 11:58:08 9329233 FclRestore::OnMsgRestoreEnd() - File Statistics: Total m5], Succeeded p3], Skipped �0] Failed 50] Need Reboot l0]

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

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

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.

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

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!

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 e6AA83E21-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 t0] mins and idle timeout is 30] mins
3280  46c   11/16 13:00:39 ####### DMRRequest::SubmitInternal(1610) - Data cannot be retrieved, error=t0x8007065B:{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 :S49]
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

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.

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