CI Build: Failure in MountFailsWhenNoOnDiskVersion

One time failure:

https://gvfs.visualstudio.com/ci/_build/results?buildId=9230

It appears that the test failed because the GVFS.Mount process did not respond quickly enough and gvfs mount timed out.

What was suspicious was the time between the first two lines of the mount process log (see below).

gvfs mount will wait as long as a minute for GVFS.Mount.exe, and so it's possible that something else on the machine caused GVFS.Mount.exe to take a long time to start.

At a minimum it's worth investigating what else can be logged to understand where the time went.

----- C:\Repos\GVFSFunctionalTests\enlistment\5c85ccc3f5b748be9755\.gvfs\logs\gvfs_mount_process_20190410_180702.log -----
[2019-04-10 18:07:13 +00:00] GVFSMount (Start) {"Version":"0.2.19100.3","EnlistmentRoot":"C:\\Repos\\GVFSFunctionalTests\\enlistment\\5c85ccc3f5b748be9755","Remote":"https://gvfs.visualstudio.com/ci/_git/ForTests","ObjectsEndpoint":"https://gvfs.visualstudio.com/ci/_git/ForTests","IsElevated":true,"EnlistmentRootPathParameter":"C:\\Repos\\GVFSFunctionalTests\\enlistment\\5c85ccc3f5b748be9755","StartedByService":"False"}
[2019-04-10 18:07:31 +00:00] RetryConfig_LoadedRetryConfig {"Area":"RetryConfig","Timeout":"00:00:30","MaxRetries":6,"Message":"RetryConfigLoaded"}
[2019-04-10 18:07:39 +00:00] GitStatusCacheConfig_Loaded {"Area":"GitStatusCacheConfig","BackOffTime":"00:00:02","Message":"GitStatusCacheConfigLoaded"}
[2019-04-10 18:07:39 +00:00] CachePathsLoaded {"gitObjectsRoot":"C:\\Repos\\GVFSFunctionalTests\\.gvfsCache\\b810a5d8b978423bb9fe3aa140499e0e\\gitObjects","localCacheRoot":"C:\\Repos\\GVFSFunctionalTests\\.gvfsCache","blobSizesRoot":"C:\\Repos\\GVFSFunctionalTests\\.gvfsCache\\b810a5d8b978423bb9fe3aa140499e0e\\blobSizes"}
[2019-04-10 18:07:39 +00:00] Mount_StartedNamedPipe {"NamedPipeName":"GVFS_C_\\REPOS\\GVFSFUNCTIONALTESTS\\ENLISTMENT\\5C85CCC3F5B748BE9755"}
[2019-04-10 18:07:40 +00:00] AttemptAnonymousAuth (Start)
[2019-04-10 18:07:41 +00:00] Error {"RepoUrl":"https://gvfs.visualstudio.com/ci/_git/ForTests","ErrorMessage":"Failed to parse credential string for approval"}
[2019-04-10 18:07:41 +00:00] NetworkResponse {"RequestId":1,"availableConnections":4,"CacheName":"","StatusCode":200,"ContentType":"application/json; charset=utf-8","connectionWaitTimeMS":"0.0095","responseWaitTimeMS":"987.7411"}
[2019-04-10 18:07:42 +00:00] AttemptAnonymousAuth (Stop) {"HttpStatus":"200","QuerySucceeded":true,"IsAnonymous":true,"DurationMs":2270}
[2019-04-10 18:07:42 +00:00] Information {"Message":"Git status cache enabled. Backoff time: 2000ms"}
[2019-04-10 18:07:43 +00:00] BlobSize_Initialize_db_settings {"Area":"BlobSizes","user_version":1,"synchronous":2}
[2019-04-10 18:07:43 +00:00] FileSystemCallbacks_Constructor {"placeholders.Count":8,"background.Count":0,"Message":"FileSystemCallbacks created"}
[2019-04-10 18:07:43 +00:00] RemoveEntriesWithParentFolderEntry (Start)
[2019-04-10 18:07:43 +00:00] RemoveEntriesWithParentFolderEntry (Stop) {"startingCount":2,"EndCount":2,"DurationMs":4}
[2019-04-10 18:07:44 +00:00] ParseGitIndex (Start)
[2019-04-10 18:07:44 +00:00] ExpandPool (Start)
[2019-04-10 18:07:44 +00:00] ExpandPool (Stop) {"Area":"GitIndexProjection","PoolType":"FolderData","PreviousSize":148,"NewSize":170,"DurationMs":0}
[2019-04-10 18:07:44 +00:00] ExpandPool (Start)
[2019-04-10 18:07:44 +00:00] ExpandPool (Stop) {"Area":"GitIndexProjection","PoolType":"FolderData","PreviousSize":170,"NewSize":196,"DurationMs":0}
[2019-04-10 18:07:44 +00:00] ExpandPool (Start)
[2019-04-10 18:07:44 +00:00] ExpandPool (Stop) {"Area":"GitIndexProjection","PoolType":"FolderData","PreviousSize":196,"NewSize":225,"DurationMs":0}
[2019-04-10 18:07:44 +00:00] ExpandPool (Start)
[2019-04-10 18:07:44 +00:00] ExpandPool (Stop) {"Area":"GitIndexProjection","PoolType":"FolderData","PreviousSize":225,"NewSize":259,"DurationMs":0}
[2019-04-10 18:07:44 +00:00] ExpandPool (Start)
[2019-04-10 18:07:44 +00:00] ExpandPool (Stop) {"Area":"GitIndexProjection","PoolType":"FolderData","PreviousSize":259,"NewSize":298,"DurationMs":0}
[2019-04-10 18:07:44 +00:00] ExpandPool (Start)
[2019-04-10 18:07:44 +00:00] ExpandPool (Stop) {"Area":"GitIndexProjection","PoolType":"FolderData","PreviousSize":298,"NewSize":343,"DurationMs":0}
[2019-04-10 18:07:44 +00:00] Information {"Message":"Finished parsing 873 index entries."}
[2019-04-10 18:07:44 +00:00] ShrinkPool (Start)
[2019-04-10 18:07:44 +00:00] ShrinkPool (Stop) {"Area":"GitIndexProjection","PoolType":"FolderData","CurrentSize":343,"didShrink":false,"shrinkToSize":372,"DurationMs":0}
[2019-04-10 18:07:44 +00:00] ShrinkPool (Start)
[2019-04-10 18:07:44 +00:00] ShrinkPool (Stop) {"Area":"GitIndexProjection","PoolType":"FileData","CurrentSize":960,"didShrink":false,"shrinkToSize":959,"DurationMs":0}
[2019-04-10 18:07:44 +00:00] ShrinkPool (Start)
[2019-04-10 18:07:44 +00:00] ShrinkPool (Stop) {"Area":"GitIndexProjection","PoolType":"Byte","CurrentSize":26190,"didShrink":false,"shrinkToSize":26070,"DurationMs":0}
[2019-04-10 18:07:44 +00:00] ShrinkPool (Start)
[2019-04-10 18:07:44 +00:00] ShrinkPool (Stop) {"Area":"GitIndexProjection","PoolType":"LazyUTF8String","CurrentSize":2095,"didShrink":true,"shrinkToSize":1874,"DurationMs":0}
[2019-04-10 18:07:44 +00:00] ParseGitIndex (Stop) {"Area":"GitIndexProjection","SortedFolderEntries_FolderPoolSize":343,"SortedFolderEntries_FilePoolSize":960,"LazyUTF8String_StringPoolSize":1874,"LazyUTF8String_BytePoolSize":26190,"DurationMs":119}
[2019-04-10 18:07:46 +00:00] InitializeEnumerationPatternMatcher {"projFSPatternMatchingWorks":true}
[2019-04-10 18:07:47 +00:00] Mount {"Message":"Virtual repo is ready"}
[2019-04-10 18:08:02 +00:00] Information {"Message":"GitStatusCache.RebuildStatusCacheIfNeeded: Done generating status. Cache state: Clean. Status scan time: 14.69s."}
[2019-04-10 18:08:10 +00:00] TryAcquireLockExternal {"LockRequest":"gvfs unmount (7272)","IsElevated":true,"Result":"Accepted"}
[2019-04-10 18:08:14 +00:00] Heartbeat {"ModifiedPathsCount":2,"PlaceholderCount":8,"GitStatusCache.StatusScanCount":1,"EnlistmentId":"4f17be1dbcc140f58432601f8b52b46d","PhysicalDiskInfo":{"DriveLetter":"C","VolumeDriveType":"Fixed","VolumeFileSystem":"NTFS","VolumeFileSystemLabel":"","VolumeSize":"136364093440","VolumeSizeRemaining":"54823940096"},"Version":"0.2.19100.3","MinutesUptime":0,"MinutesSinceLast":0}
[2019-04-10 18:08:14 +00:00] GVFSMount (Stop) {"DurationMs":72823}

Start with the MountFailsWhenNoOnDiskVersion test and the GVFS.Mount.exe startup path invoked by gvfs mount. Compare the supplied mount-process timestamps with the one-minute timeout and determine which startup stages need additional logging. Done means the delay is explained by actionable logs and the intermittent failure can be diagnosed.