Shadow Folder Fails on First Check of the day

[edonaldson]

The first checkin that we try to do during the day inevitably fails to shadow with the following error in the shadow log:

---
2/12/2009 12:35:58 PM <generic>: [<No Name>:2752] GetEntryAssembly() returned null; not logging assembly name
2/12/2009 12:35:58 PM <generic>: [<No Name>:2752] Starting Shadow Folder Thread for repository 14.
2/12/2009 12:35:58 PM <generic>: [<No Name>:3616] Shadow Folder is using the folder, C:\WINDOWS\TEMP\, as a TEMP directory.
2/12/2009 12:35:58 PM <generic>: [<No Name>:2752] Shadow Folder Thread for repository 14 started.
2/12/2009 12:36:02 PM <generic>: [<No Name>:3616] Vault's Shadow Folders attempting get (by Delta) for wwwroota
2/12/2009 12:36:03 PM <generic>: [<No Name>:3616] Vault Shadow Folder encountered a problem: [VaultClientOperationsLib.GetLatestVersionFailedException: Exception of type 'VaultClientOperationsLib.GetLatestVersionFailedException' was thrown.
at VaultClientOperationsLib.ClientInstance.ProcessGetFileRequests(GetFileInfo[] infos, MakeWritableType makeWritable, SetFileTimeType setFileTime, MergeType merge, Boolean updateHiddenFilesOnly, String ancestorFullPath, Boolean flat, String ancestorDiskPath, OverwritePrompt PromptData, Boolean isLabelGet, String currentPathToLabelItem, Int64 labelID, Boolean isRetry, Boolean isGetByDisplayVersion)
at VaultClientOperationsLib.ClientInstance.Get(VaultClientFile[] files, Boolean forceLatest, MakeWritableType makeWritable, SetFileTimeType setFileTime, MergeType merge, OverwritePrompt PromptData)
at VaultShadowFolder.VaultShadowFolderRepository.VaultShadowFolderRepositoryProc()]Exception of type 'VaultClientOperationsLib.GetLatestVersionFailedException' was thrown.
at VaultClientOperationsLib.ClientInstance.ProcessGetFileRequests(GetFileInfo[] infos, MakeWritableType makeWritable, SetFileTimeType setFileTime, MergeType merge, Boolean updateHiddenFilesOnly, String ancestorFullPath, Boolean flat, String ancestorDiskPath, OverwritePrompt PromptData, Boolean isLabelGet, String currentPathToLabelItem, Int64 labelID, Boolean isRetry, Boolean isGetByDisplayVersion)
at VaultClientOperationsLib.ClientInstance.Get(VaultClientFile[] files, Boolean forceLatest, MakeWritableType makeWritable, SetFileTimeType setFileTime, MergeType merge, OverwritePrompt PromptData)
at VaultShadowFolder.VaultShadowFolderRepository.VaultShadowFolderRepositoryProc()
---------------------------------------

And these are from the log, which is already in debug mode:

---------------------------------------

----2/12/2009 12:35:55 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled EndTx: Finished Applying CheckIn to $/wwwrootd/dfs/Default.asp
----2/12/2009 12:35:55 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: ListWatchers started.
----2/12/2009 12:35:55 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: ListWatchers finished.
----2/12/2009 12:35:55 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: CreateBubbleFolders started.
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: CreateBubbleFolders finished.
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: CreateHistoryItems started.
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: CreateHistoryItems finished.
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: SaveFoldersEntryDeltas started.
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: SaveFoldersEntryDeltas finished.
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: SaveCurrentTreeFolders started.
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: SaveCurrentTreeFolders finished.
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: LockCheckoutList started.
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: CreateDBLockObject started.
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: CreateDBLockObject finished.
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: LockCheckoutList finished.
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: ReleaseLocks started.
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: ReleaseLocks finished.
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: CloseSCCTransaction started.
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: CloseSCCTransaction finished.
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled EndTx(): Begin commit changes for TxID 2383, which will release repository lock.
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled SQL transaction 14867369 successfully committed.
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled Released repository lock for TxID 2383
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled EndTx(): End commit changes for TxID 2383
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled EndTx(): Begin cache tree changes for TxID 2383
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled EndTx(): End cache tree changes for TxID 2383
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled Beginning SQL transaction 63406242
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: DeletePendingTransactionObjects started.
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: DeletePendingTransactionObjects finished.
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled SQL transaction 63406242 successfully committed.
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled TreeManager Signal - Tx End - TxID:2383 CacheLockId:66697461 RepID:14
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: DeleteSessionBranchSandbox started.
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: DeleteSessionBranchSandbox finished.
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled Creating plugin thread...
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled (a4fdc150-2944-4e73-98eb-f913c516353f) EndTx (Revision - 2383) returned: Success
----2/12/2009 12:35:56 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled ASMX: EndTx finished.
----2/12/2009 12:35:57 PM --()-- DB: GetPluginInfo started.
----2/12/2009 12:35:57 PM --()-- DB: GetPluginInfo finished.
----2/12/2009 12:35:57 PM --()-- Retrieved 1 pluginInfos for this type
----2/12/2009 12:35:57 PM --()-- Calling plugin at location :http://sourcegear.summitmg.com/VaultSha ... rvice.asmx
----2/12/2009 12:35:57 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled ASMX: GetRepositoryStructure started.
----2/12/2009 12:35:57 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled Getting repository Structure-> Rep ID: 14 Base: 2382 Target: -1
----2/12/2009 12:35:57 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: GetUserRepositoryLastChange started.
----2/12/2009 12:35:57 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: GetUserRepositoryLastChange finished.
----2/12/2009 12:35:57 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: GetLatestRepositoryInfo started.
----2/12/2009 12:35:57 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: GetLatestRepositoryInfo finished.
----2/12/2009 12:35:57 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled TreeManager: cache matches repository revision and folder security hasn't changed. Returning cached tree, revID 2383
----2/12/2009 12:35:57 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: GetLastTreeSecurityChange started.
----2/12/2009 12:35:57 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: GetLastTreeSecurityChange finished.
----2/12/2009 12:35:57 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled VaultServiceAPI::GetRepositoryTreeDelta() UserID:4 RepID:14 Base:2382 Target:2383 Calling VaultRepUtil.DiffRepTrees() - in-memory tree diff.
----2/12/2009 12:35:57 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled ASMX: GetRepositoryStructure finished.
----2/12/2009 12:35:57 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled GetRepositoryStructure returned: Success
----2/12/2009 12:35:58 PM --()-- Successfully called plugin at location :http://sourcegear.summitmg.com/VaultSha ... rvice.asmx
----2/12/2009 12:35:58 PM --()-- Exiting plugin thread
----2/12/2009 12:35:58 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled Getting list of checkout changes.
----2/12/2009 12:35:58 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled ASMX: GetCheckOutListChanges started.
----2/12/2009 12:35:58 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: GetUserRepositoryLastChange started.
----2/12/2009 12:35:58 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: GetUserRepositoryLastChange finished.
----2/12/2009 12:35:58 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled Beginning SQL transaction 41462866
----2/12/2009 12:35:58 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled GetCheckoutListChanges: Transaction Started
----2/12/2009 12:35:58 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: LockCheckoutList started.
----2/12/2009 12:35:58 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: CreateDBLockObject started.
----2/12/2009 12:35:58 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: CreateDBLockObject finished.
----2/12/2009 12:35:58 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: LockCheckoutList finished.
----2/12/2009 12:35:58 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: GetCurrentCheckoutInfo started.
----2/12/2009 12:35:58 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: GetCurrentCheckoutInfo finished.
----2/12/2009 12:35:58 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: GetLatestRepositoryInfo started.
----2/12/2009 12:35:58 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: GetLatestRepositoryInfo finished.
----2/12/2009 12:35:58 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled TreeManager: cache matches repository revision and folder security hasn't changed. Returning cached tree, revID 2383
----2/12/2009 12:35:58 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: GetFSLockChanges started.
----2/12/2009 12:35:58 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled DB: GetFSLockChanges finished.
----2/12/2009 12:35:58 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled VaultServiceAPI::GetCheckoutListChanges() Status:0 UserID:4 RepID:14 FolderSecurity:False BaseList:5988 Target List:5989 RefreshFlag:False
----2/12/2009 12:35:58 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled SQL transaction 41462866 successfully committed.
----2/12/2009 12:35:58 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled GetCheckoutListChanges: Transaction Committed
----2/12/2009 12:35:58 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled GetCheckOutListChanges returned: Success
----2/12/2009 12:35:58 PM edonalds--ATL-EDONALDS(10.110.2.29)--SSL Disabled ASMX: GetCheckOutListChanges finished.

---------------------------------------

The interesting thing is that we aren't making a modification in the wwwroota share. It's in another share. But it's always the wwwroota share that fails (maybe because it's alphabetical, or maybe it was the first share created). We have shares wwwroota-wwwrootz, and others.

We are running Version 4.1.3.18280

Now, of course, if we don't notice that the shadow failed, our shadow folders become out of sync. Is there any way to force a recheck and resync of the shadow folders?

[lbauer]

That's strange. Does the first checkin of the day follow a Vault server restart? I can't tell from the server log. Is there anything in the server log that corresponds to this time in the Shadow Folder log?

2/12/2009 12:36:02 PM <generic>: [<No Name>:3616] Vault's Shadow Folders attempting get (by Delta) for wwwroota
2/12/2009 12:36:03 PM

You can make sure the shadow folders remain synced if you choose the Synchronize with Repository option instead of the default Optimize for Speed option in the Shadow Folder configuration in the Admin Web Client. This takes more resources, though.

[edonaldson]

We do not normally restart the server during the evening, so I cannot determine if that is the case. I will try again tomorrow, and perhaps it is related to a restart, which, of course, is still bad.

We cannot run the shadow in Synchronise with Repository mode, as there are files that are added outside Vault (via uploads) and it's my understand that the Synchronise with Repository would remove them.

[lbauer]

The server can restart on its own, due to IIS configuration. Check for "System Started" in the Vault Server log to see if there's a regular restart.