diff --git a/GVFS/GVFS.Common/Git/GVFSGitObjects.cs b/GVFS/GVFS.Common/Git/GVFSGitObjects.cs index b9044b2be..0c27a5316 100644 --- a/GVFS/GVFS.Common/Git/GVFSGitObjects.cs +++ b/GVFS/GVFS.Common/Git/GVFSGitObjects.cs @@ -33,14 +33,48 @@ public enum RequestSource SymLinkCreation, } + /// + /// Why a blob-hydration request ultimately failed. Recorded on the terminal failure + /// telemetry so failures outside gvfs.exe's control (network, local disk/IO, ProjFS) + /// can be told apart from failures that point at an actionable bug or a server/data + /// problem. Kept in sync with the telemetry bucketing in the devprod.git.telemetry + /// workbook (gvfs-regression-signatures.kql). + /// + public enum BlobHydrationFailureCategory + { + None = 0, + + // Outside gvfs.exe's control: + NetworkUnavailable, // A network/HTTP-layer exception while fetching the blob. + DownloadFailed, // The blob download reported failure (transient/unclassified). + LocalIO, // IOException reading the local object or streaming to the ProjFS buffer. + ProjFSWriteFailed, // ProjFS WriteFileData returned a non-recoverable error. + + // Actionable (bug, corruption, or server/data problem): + ObjectNotOnServer, // The cache server returned 404 for the blob. + LocalCopyFailed, // Blob downloaded, but the subsequent local copy still failed. + SizeMismatch, // Blob length did not match the length ProjFS requested. + Unexpected, // Unclassified exception. + } + protected GVFSContext Context { get; private set; } public virtual bool TryCopyBlobContentStream( string sha, CancellationToken cancellationToken, RequestSource requestSource, - Action writeAction) + Action writeAction, + out BlobHydrationFailureCategory failureCategory) { + // Track the outcome of the most recent attempt so that the terminal failure + // telemetry can attribute the failure to a cause (network vs. object-missing vs. + // local copy) that is otherwise collapsed into the bool return value below. The + // final category is also surfaced via the out parameter so the caller can tag its + // own terminal telemetry with the same cause. + DownloadAndSaveObjectResult lastDownloadResult = DownloadAndSaveObjectResult.Error; + bool downloadSucceededButCopyFailed = false; + BlobHydrationFailureCategory capturedCategory = BlobHydrationFailureCategory.None; + RetryWrapper retrier = new RetryWrapper(this.GitObjectRequestor.RetryConfig.MaxAttempts, cancellationToken); retrier.OnFailure += errorArgs => @@ -50,10 +84,35 @@ public virtual bool TryCopyBlobContentStream( metadata.Add("AttemptNumber", errorArgs.TryCount); metadata.Add("WillRetry", errorArgs.WillRetry); + BlobHydrationFailureCategory category; if (errorArgs.Error != null) { metadata.Add("Exception", errorArgs.Error.ToString()); + + // An IOException here can also originate in the download/network layer, but + // we cannot tell where it came from, so it is bucketed as local IO. + category = errorArgs.Error is IOException + ? BlobHydrationFailureCategory.LocalIO + : BlobHydrationFailureCategory.NetworkUnavailable; } + else if (downloadSucceededButCopyFailed) + { + category = BlobHydrationFailureCategory.LocalCopyFailed; + } + else if (lastDownloadResult == DownloadAndSaveObjectResult.ObjectNotOnServer) + { + category = BlobHydrationFailureCategory.ObjectNotOnServer; + } + else + { + // The download reported failure without an exception; the cause (network, + // disk-save, etc.) is unclassified, so use the neutral DownloadFailed bucket + // rather than over-asserting NetworkUnavailable. + category = BlobHydrationFailureCategory.DownloadFailed; + } + + capturedCategory = category; + metadata.Add(nameof(BlobHydrationFailureCategory), category.ToString()); string message = "TryCopyBlobContentStream: Failed to provide blob contents"; if (errorArgs.WillRetry) @@ -76,19 +135,25 @@ public virtual bool TryCopyBlobContentStream( } else { + downloadSucceededButCopyFailed = false; + // Pass in false for retryOnFailure because the retrier in this method manages multiple attempts - if (this.TryDownloadAndSaveObject(sha, cancellationToken, requestSource, retryOnFailure: false) == DownloadAndSaveObjectResult.Success) + lastDownloadResult = this.TryDownloadAndSaveObject(sha, cancellationToken, requestSource, retryOnFailure: false); + if (lastDownloadResult == DownloadAndSaveObjectResult.Success) { if (this.Context.Repository.TryCopyBlobContentStream(sha, writeAction)) { return new RetryWrapper.CallbackResult(true); } + + downloadSucceededButCopyFailed = true; } return new RetryWrapper.CallbackResult(error: null, shouldRetry: true); } }); + failureCategory = invokeResult.Result ? BlobHydrationFailureCategory.None : capturedCategory; return invokeResult.Result; } diff --git a/GVFS/GVFS.Platform.Windows/WindowsFileSystemVirtualizer.cs b/GVFS/GVFS.Platform.Windows/WindowsFileSystemVirtualizer.cs index a4bea9068..7a6bad6f2 100644 --- a/GVFS/GVFS.Platform.Windows/WindowsFileSystemVirtualizer.cs +++ b/GVFS/GVFS.Platform.Windows/WindowsFileSystemVirtualizer.cs @@ -59,6 +59,24 @@ public class WindowsFileSystemVirtualizer : FileSystemVirtualizer, IRequiredCall // the throttle cannot be disturbed by wall-clock adjustments. private long lastEnumerationEvictionSweepTickCount = Environment.TickCount64; + // Enumeration IDs recently removed by EvictStaleEnumerations, mapped to the monotonic tick at + // which they were evicted. Retained briefly so a later GetDirectoryEnumeration for an evicted + // ID can be attributed to GVFS eviction (self-inflicted) rather than a ProjFS unknown-ID + // delivery. Bounded by pruning during each sweep; empty while eviction is disabled (the default). + private readonly ConcurrentDictionary recentlyEvictedEnumerations = new ConcurrentDictionary(); + + /// + /// Why a GetDirectoryEnumeration failed to find its enumeration ID. Recorded on the failure + /// telemetry so a self-inflicted eviction can be told apart from a ProjFS unknown-ID delivery. + /// Kept in sync with the telemetry bucketing in devprod.git.telemetry + /// (gvfs-regression-signatures.kql). + /// + public enum EnumerationFailureReason + { + Unknown = 0, // ProjFS delivered an ID GVFS never held or already ended (outside gvfs.exe's control). + Evicted, // GVFS's own stale-enumeration eviction removed a live enumeration (self-inflicted). + } + public WindowsFileSystemVirtualizer(GVFSContext context, GVFSGitObjects gitObjects) : this( context, @@ -187,19 +205,51 @@ private void MaybeEvictStaleEnumerations() private void EvictStaleEnumerations() { + long now = Environment.TickCount64; + + // Prune the eviction-tracking map on every sweep, independent of whether an eviction + // happens this pass, so entries never outlive the window in which a stale + // GetDirectoryEnumeration could still arrive for an evicted ID. (If this ran only when + // Count > max below, the last evicted batch would linger once activity subsided.) Guids + // are never reused, so there is no need to prune on re-add. Cheap no-op while empty + // (the default, since eviction is off). + if (!this.recentlyEvictedEnumerations.IsEmpty) + { + long trackingCutoff = now - (long)(2 * this.activeEnumerationStaleTimeout.TotalMilliseconds); + foreach (KeyValuePair tracked in this.recentlyEvictedEnumerations) + { + if (tracked.Value < trackingCutoff) + { + this.recentlyEvictedEnumerations.TryRemove(tracked.Key, out _); + } + } + } + if (this.activeEnumerations.Count <= this.maxActiveEnumerations) { return; } - long cutoff = Environment.TickCount64 - (long)this.activeEnumerationStaleTimeout.TotalMilliseconds; + long cutoff = now - (long)this.activeEnumerationStaleTimeout.TotalMilliseconds; int evictedCount = 0; foreach (KeyValuePair entry in this.activeEnumerations) { - if (entry.Value.LastActivityTickCount < cutoff && - this.activeEnumerations.TryRemove(entry.Key, out _)) + if (entry.Value.LastActivityTickCount < cutoff) { - evictedCount++; + // Record the eviction BEFORE removing from activeEnumerations so a concurrent + // GetDirectoryEnumeration for this ID always finds it in one map or the other, + // and is never mis-attributed to a ProjFS unknown-ID delivery. + this.recentlyEvictedEnumerations[entry.Key] = now; + if (this.activeEnumerations.TryRemove(entry.Key, out _)) + { + evictedCount++; + } + else + { + // Lost the race (e.g. a normal EndDirectoryEnumeration removed it first); + // it was not evicted by us, so undo the tracking entry. + this.recentlyEvictedEnumerations.TryRemove(entry.Key, out _); + } } } @@ -464,6 +514,16 @@ public HResult GetDirectoryEnumerationCallback( EventMetadata metadata = this.CreateEventMetadata(enumerationId); metadata.Add("filterFileName", filterFileName); metadata.Add("restartScan", restartScan); + + // Distinguish a failure caused by GVFS's own stale-enumeration eviction + // (self-inflicted, fixable) from ProjFS delivering an ID GVFS never held or + // already ended (outside gvfs.exe's control). Kept in sync with the telemetry + // bucketing in devprod.git.telemetry (gvfs-regression-signatures.kql). + EnumerationFailureReason enumerationFailureReason = this.recentlyEvictedEnumerations.ContainsKey(enumerationId) + ? EnumerationFailureReason.Evicted + : EnumerationFailureReason.Unknown; + metadata.Add(nameof(EnumerationFailureReason), enumerationFailureReason.ToString()); + this.Context.Tracer.RelatedError(metadata, nameof(this.GetDirectoryEnumerationCallback) + ": Failed to find active enumeration ID"); return HResult.InternalError; @@ -1180,6 +1240,7 @@ private void GetFileStreamHandlerAsyncHandler( if (blobLength != length) { requestMetadata.Add("blobLength", blobLength); + requestMetadata.Add(nameof(GVFSGitObjects.BlobHydrationFailureCategory), GVFSGitObjects.BlobHydrationFailureCategory.SizeMismatch.ToString()); this.Context.Tracer.RelatedError(requestMetadata, $"{nameof(this.GetFileStreamHandlerAsyncHandler)}: Actual file length (blobLength) does not match requested length"); throw new GetFileStreamException(HResult.InternalError); @@ -1204,6 +1265,7 @@ private void GetFileStreamHandlerAsyncHandler( catch (IOException e) { requestMetadata.Add("Exception", e.ToString()); + requestMetadata.Add(nameof(GVFSGitObjects.BlobHydrationFailureCategory), GVFSGitObjects.BlobHydrationFailureCategory.LocalIO.ToString()); this.Context.Tracer.RelatedError(requestMetadata, "IOException while copying to unmanaged buffer."); throw new GetFileStreamException("IOException while copying to unmanaged buffer: " + e.Message, (HResult)HResultExtensions.HResultFromNtStatus.FileNotAvailable); @@ -1225,6 +1287,7 @@ private void GetFileStreamHandlerAsyncHandler( default: { + requestMetadata.Add(nameof(GVFSGitObjects.BlobHydrationFailureCategory), GVFSGitObjects.BlobHydrationFailureCategory.ProjFSWriteFailed.ToString()); this.Context.Tracer.RelatedError(requestMetadata, $"{nameof(this.virtualizationInstance.WriteFileData)} failed, error: " + writeResult.ToString("X") + "(" + writeResult.ToString("G") + ")"); } @@ -1235,8 +1298,10 @@ private void GetFileStreamHandlerAsyncHandler( } } } - })) + }, + out GVFSGitObjects.BlobHydrationFailureCategory failureCategory)) { + requestMetadata.Add(nameof(GVFSGitObjects.BlobHydrationFailureCategory), failureCategory.ToString()); this.Context.Tracer.RelatedError(requestMetadata, $"{nameof(this.GetFileStreamHandlerAsyncHandler)}: TryCopyBlobContentStream failed"); this.TryCompleteCommand(commandId, (HResult)HResultExtensions.HResultFromNtStatus.FileNotAvailable); @@ -1264,6 +1329,7 @@ private void GetFileStreamHandlerAsyncHandler( catch (Exception e) { requestMetadata.Add("Exception", e.ToString()); + requestMetadata.Add(nameof(GVFSGitObjects.BlobHydrationFailureCategory), GVFSGitObjects.BlobHydrationFailureCategory.Unexpected.ToString()); this.Context.Tracer.RelatedError(requestMetadata, $"{nameof(this.GetFileStreamHandlerAsyncHandler)}: TryCopyBlobContentStream failed"); this.TryCompleteCommand(commandId, (HResult)HResultExtensions.HResultFromNtStatus.FileNotAvailable); diff --git a/GVFS/GVFS.UnitTests/Git/GVFSGitObjectsTests.cs b/GVFS/GVFS.UnitTests/Git/GVFSGitObjectsTests.cs index caa23da24..dea5efc62 100644 --- a/GVFS/GVFS.UnitTests/Git/GVFSGitObjectsTests.cs +++ b/GVFS/GVFS.UnitTests/Git/GVFSGitObjectsTests.cs @@ -11,6 +11,7 @@ using System; using System.Collections.Generic; using System.IO; +using System.Linq; using System.Net; using System.Reflection; using System.Threading; @@ -56,11 +57,124 @@ public void CatchesFileNotFoundAfterFileDeleted() ValidTestObjectFileSha1, new CancellationToken(), GVFSGitObjects.RequestSource.FileStreamCallback, - (stream, length) => Assert.Fail("Should not be able to call copy stream callback")) + (stream, length) => Assert.Fail("Should not be able to call copy stream callback"), + out GVFSGitObjects.BlobHydrationFailureCategory _) .ShouldEqual(false); } } + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void TerminalBlobHydrationFailureIsTaggedWithCategory() + { + MockFileSystemWithCallbacks fileSystem = new MockFileSystemWithCallbacks(); + fileSystem.OnFileExists = (path) => true; + fileSystem.OnOpenFileStream = (path, fileMode, fileAccess) => + { + if (fileAccess == FileAccess.Write) + { + return new MemoryStream(); + } + + throw new FileNotFoundException(); + }; + + MockHttpGitObjects httpObjects = new MockHttpGitObjects(); + using (httpObjects.InputStream = new MemoryStream(this.validTestObjectFileContents)) + { + httpObjects.MediaType = GVFSConstants.MediaTypes.LooseObjectMediaType; + GVFSGitObjects dut = this.CreateTestableGVFSGitObjects(httpObjects, fileSystem, out MockTracer tracer); + + bool copied = dut.TryCopyBlobContentStream( + ValidTestObjectFileSha1, + new CancellationToken(), + GVFSGitObjects.RequestSource.FileStreamCallback, + (stream, length) => Assert.Fail("Should not be able to call copy stream callback"), + out GVFSGitObjects.BlobHydrationFailureCategory failureCategory); + copied.ShouldEqual(false); + + // The terminal failure carries a specific BlobHydrationFailureCategory so telemetry + // can tell failures outside gvfs.exe's control apart from actionable ones. Here the + // local copy misses and the download then fails, so the cause is NetworkUnavailable — + // surfaced both on the telemetry event and via the out parameter. + failureCategory.ShouldEqual(GVFSGitObjects.BlobHydrationFailureCategory.NetworkUnavailable); + string terminalError = tracer.RelatedErrorEvents.First(e => e.Contains("Failed to provide blob contents")); + terminalError.ShouldContain("\"BlobHydrationFailureCategory\":\"NetworkUnavailable\""); + } + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void TerminalBlobHydrationFailureTagsObjectNotOnServer() + { + MockFileSystemWithCallbacks fileSystem = new MockFileSystemWithCallbacks(); + fileSystem.OnFileExists = (path) => true; + fileSystem.OnOpenFileStream = (path, mode, access) => + { + if (access == FileAccess.Write) + { + return new MemoryStream(); + } + + throw new FileNotFoundException(); + }; + + MockHttpGitObjects httpObjects = new MockHttpGitObjects(); + httpObjects.StatusCodeToReturn = HttpStatusCode.NotFound; + GVFSGitObjects dut = this.CreateTestableGVFSGitObjects(httpObjects, fileSystem, out MockTracer tracer); + + bool copied = dut.TryCopyBlobContentStream( + ValidTestObjectFileSha1, + new CancellationToken(), + GVFSGitObjects.RequestSource.FileStreamCallback, + (stream, length) => Assert.Fail("Should not be able to call copy stream callback"), + out GVFSGitObjects.BlobHydrationFailureCategory failureCategory); + copied.ShouldEqual(false); + + // The server returned 404, so the blob is genuinely missing on the server (actionable). + failureCategory.ShouldEqual(GVFSGitObjects.BlobHydrationFailureCategory.ObjectNotOnServer); + string terminalError = tracer.RelatedErrorEvents.First(e => e.Contains("Failed to provide blob contents")); + terminalError.ShouldContain("\"BlobHydrationFailureCategory\":\"ObjectNotOnServer\""); + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void TerminalBlobHydrationFailureTagsLocalCopyFailed() + { + MockFileSystemWithCallbacks fileSystem = new MockFileSystemWithCallbacks(); + fileSystem.OnFileExists = (path) => true; + fileSystem.OnOpenFileStream = (path, mode, access) => + { + if (access == FileAccess.Write) + { + return new MemoryStream(); + } + + throw new FileNotFoundException(); + }; + fileSystem.OnMoveFile = (source, target) => { }; + + MockHttpGitObjects httpObjects = new MockHttpGitObjects(); + + // Serve fresh content on every attempt so the download succeeds; the failure must then be + // attributed to the local copy that keeps failing afterward, not to the download. + httpObjects.ContentBytesToServe = this.validTestObjectFileContents; + httpObjects.MediaType = GVFSConstants.MediaTypes.LooseObjectMediaType; + GVFSGitObjects dut = this.CreateTestableGVFSGitObjects(httpObjects, fileSystem, out MockTracer tracer); + + bool copied = dut.TryCopyBlobContentStream( + ValidTestObjectFileSha1, + new CancellationToken(), + GVFSGitObjects.RequestSource.FileStreamCallback, + (stream, length) => Assert.Fail("Should not be able to call copy stream callback"), + out GVFSGitObjects.BlobHydrationFailureCategory failureCategory); + copied.ShouldEqual(false); + + failureCategory.ShouldEqual(GVFSGitObjects.BlobHydrationFailureCategory.LocalCopyFailed); + string terminalError = tracer.RelatedErrorEvents.First(e => e.Contains("Failed to provide blob contents")); + terminalError.ShouldContain("\"BlobHydrationFailureCategory\":\"LocalCopyFailed\""); + } + [TestCase] public void SucceedsForNormalLookingLooseObjectDownloads() { @@ -541,12 +655,18 @@ private void AssertRetryableExceptionOnDownload( private GVFSGitObjects CreateTestableGVFSGitObjects(GitObjectsHttpRequestor httpObjects, MockFileSystemWithCallbacks fileSystem) { - MockTracer tracer = new MockTracer(); + return this.CreateTestableGVFSGitObjects(httpObjects, fileSystem, out _); + } + + private GVFSGitObjects CreateTestableGVFSGitObjects(GitObjectsHttpRequestor httpObjects, MockFileSystemWithCallbacks fileSystem, out MockTracer tracer) + { + MockTracer localTracer = new MockTracer(); + tracer = localTracer; GVFSEnlistment enlistment = new GVFSEnlistment(TestEnlistmentRoot, "https://fakeRepoUrl", "fakeGitBinPath", authentication: null); enlistment.InitializeCachePathsFromKey(TestLocalCacheRoot, TestObjectRoot); - GitRepo repo = new GitRepo(tracer, enlistment, fileSystem, () => new MockLibGit2Repo(tracer)); + GitRepo repo = new GitRepo(localTracer, enlistment, fileSystem, () => new MockLibGit2Repo(localTracer)); - GVFSContext context = new GVFSContext(tracer, fileSystem, repo, enlistment); + GVFSContext context = new GVFSContext(localTracer, fileSystem, repo, enlistment); GVFSGitObjects dut = new UnsafeGVFSGitObjects(context, httpObjects); return dut; } @@ -565,6 +685,8 @@ private MockHttpGitObjects(MockGVFSEnlistment enlistment) public Stream InputStream { get; set; } public string MediaType { get; set; } + public HttpStatusCode? StatusCodeToReturn { get; set; } + public byte[] ContentBytesToServe { get; set; } public static MemoryStream GetRandomStream(int size) { @@ -595,10 +717,26 @@ public override RetryWrapper.InvocationResult TryDownloadOb Action.ErrorEventArgs> onFailure, bool preferBatchedLooseObjects) { + if (this.StatusCodeToReturn.HasValue) + { + // Simulate the server returning a non-OK status (e.g. 404) so callers can exercise + // the ObjectNotOnServer path. + return new RetryWrapper.InvocationResult( + 0, + error: null, + result: new GitObjectTaskResult(this.StatusCodeToReturn.Value)); + } + + // Serve a fresh stream per call when ContentBytesToServe is set so the download + // succeeds even across retries (InputStream would be consumed after the first read). + Stream contentStream = this.ContentBytesToServe != null + ? new MemoryStream(this.ContentBytesToServe) + : this.InputStream; + using (GitEndPointResponseData response = new GitEndPointResponseData( HttpStatusCode.OK, this.MediaType, - this.InputStream, + contentStream, message: null, onResponseDisposed: null)) { diff --git a/GVFS/GVFS.UnitTests/Mock/Git/MockGVFSGitObjects.cs b/GVFS/GVFS.UnitTests/Mock/Git/MockGVFSGitObjects.cs index b95984ecc..bb3433287 100644 --- a/GVFS/GVFS.UnitTests/Mock/Git/MockGVFSGitObjects.cs +++ b/GVFS/GVFS.UnitTests/Mock/Git/MockGVFSGitObjects.cs @@ -20,6 +20,8 @@ public MockGVFSGitObjects(GVFSContext context, GitObjectsHttpRequestor httpGitOb } public bool CancelTryCopyBlobContentStream { get; set; } + public bool ThrowOnTryCopyBlobContentStream { get; set; } + public bool ThrowIOExceptionDuringCopy { get; set; } public uint FileLength { get; set; } = DefaultFileLength; public override bool TryDownloadCommit(string objectSha) @@ -43,13 +45,31 @@ public override bool TryCopyBlobContentStream( string sha, CancellationToken cancellationToken, RequestSource requestSource, - Action writeAction) + Action writeAction, + out GVFSGitObjects.BlobHydrationFailureCategory failureCategory) { + failureCategory = GVFSGitObjects.BlobHydrationFailureCategory.None; + if (this.CancelTryCopyBlobContentStream) { throw new OperationCanceledException(); } + if (this.ThrowOnTryCopyBlobContentStream) + { + // A non-cancellation, non-GetFileStreamException exception exercises the generic + // catch in GetFileStreamHandlerAsyncHandler (BlobHydrationFailureCategory.Unexpected). + throw new InvalidOperationException("Simulated unexpected hydration failure"); + } + + if (this.ThrowIOExceptionDuringCopy) + { + // The served length matches the requested length (so no size mismatch), but reading + // the blob content throws IOException, exercising the LocalIO copy-failure path. + writeAction(new ThrowOnReadStream(this.FileLength), this.FileLength); + return true; + } + writeAction( new MemoryStream(new byte[this.FileLength]), this.FileLength); @@ -57,6 +77,26 @@ public override bool TryCopyBlobContentStream( return true; } + private sealed class ThrowOnReadStream : Stream + { + public ThrowOnReadStream(long length) + { + this.Length = length; + } + + public override bool CanRead => true; + public override bool CanSeek => false; + public override bool CanWrite => false; + public override long Length { get; } + public override long Position { get; set; } + + public override int Read(byte[] buffer, int offset, int count) => throw new IOException("Simulated IO failure while reading blob content"); + public override void Flush() { } + public override long Seek(long offset, SeekOrigin origin) => throw new NotSupportedException(); + public override void SetLength(long value) => throw new NotSupportedException(); + public override void Write(byte[] buffer, int offset, int count) => throw new NotSupportedException(); + } + public override string[] ReadPackFileNames(string packFolderPath, string prefixFilter = "") { return Array.Empty(); diff --git a/GVFS/GVFS.UnitTests/Windows/Virtualization/WindowsFileSystemVirtualizerTests.cs b/GVFS/GVFS.UnitTests/Windows/Virtualization/WindowsFileSystemVirtualizerTests.cs index c2d96a446..bfd4a0e09 100644 --- a/GVFS/GVFS.UnitTests/Windows/Virtualization/WindowsFileSystemVirtualizerTests.cs +++ b/GVFS/GVFS.UnitTests/Windows/Virtualization/WindowsFileSystemVirtualizerTests.cs @@ -13,6 +13,7 @@ using System.IO; using System.Threading; using System.Threading.Tasks; +using System.Linq; using GVFS.Common.Tracing; namespace GVFS.UnitTests.Windows.Virtualization @@ -326,6 +327,42 @@ public void StaleEnumerationsAreEvictedWhenEnabledButLiveOnesAreKept() } } + [TestCase] + public void GetDirectoryEnumerationTagsEvictedVersusUnknownId() + { + using (WindowsFileSystemVirtualizerTester tester = new WindowsFileSystemVirtualizerTester(this.Repo, new[] { "test" })) + { + tester.GitIndexProjection.EnumerationInMemory = true; + + tester.WindowsVirtualizer.MaxActiveEnumerationsForTest = 1; + tester.WindowsVirtualizer.ActiveEnumerationStaleTimeoutForTest = TimeSpan.FromMilliseconds(20); + + Guid staleId = Guid.NewGuid(); + tester.MockVirtualization.RequiredCallbacks.StartDirectoryEnumerationCallback(1, staleId, "test", TriggeringProcessId, TriggeringProcessImageFileName).ShouldEqual(HResult.Ok); + + Thread.Sleep(200); + + Guid freshId = Guid.NewGuid(); + tester.MockVirtualization.RequiredCallbacks.StartDirectoryEnumerationCallback(2, freshId, "test", TriggeringProcessId, TriggeringProcessImageFileName).ShouldEqual(HResult.Ok); + + tester.WindowsVirtualizer.ForceEnumerationEvictionSweepForTest(); + + MockTracer mockTracker = this.Repo.Context.Tracer as MockTracer; + + // A Get for the evicted enumeration is attributed to GVFS eviction (self-inflicted). + // results is unused on the failure path, so null is safe. + tester.MockVirtualization.RequiredCallbacks.GetDirectoryEnumerationCallback(3, staleId, string.Empty, false, null).ShouldEqual(HResult.InternalError); + mockTracker.RelatedErrorEvents.Any( + e => e.Contains("Failed to find active enumeration ID") && e.Contains("\"EnumerationFailureReason\":\"Evicted\"")).ShouldBeTrue(); + + // A Get for an ID GVFS never held is attributed to a ProjFS unknown-ID delivery. + Guid neverSeenId = Guid.NewGuid(); + tester.MockVirtualization.RequiredCallbacks.GetDirectoryEnumerationCallback(4, neverSeenId, string.Empty, false, null).ShouldEqual(HResult.InternalError); + mockTracker.RelatedErrorEvents.Any( + e => e.Contains("Failed to find active enumeration ID") && e.Contains("\"EnumerationFailureReason\":\"Unknown\"")).ShouldBeTrue(); + } + } + [TestCase] public void GetPlaceholderInformationHandlerPathNotProjected() { @@ -600,6 +637,72 @@ public void OnGetFileStreamHandlesWriteFailure() HResult result = tester.MockVirtualization.WaitForCompletionStatus(); result.ShouldEqual(tester.MockVirtualization.WriteFileReturnResult); + + // The failure is tagged as a ProjFS write failure (a cause outside gvfs.exe's + // control) so telemetry can bucket it apart from actionable hydration failures. + MockTracer mockTracker = this.Repo.Context.Tracer as MockTracer; + mockTracker.RelatedErrorEvents.Any( + e => e.Contains("\"BlobHydrationFailureCategory\":\"ProjFSWriteFailed\"")).ShouldBeTrue(); + } + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void OnGetFileStreamTagsSizeMismatch() + { + using (WindowsFileSystemVirtualizerTester tester = new WindowsFileSystemVirtualizerTester(this.Repo)) + { + // The blob length served (FileLength) differs from the length ProjFS requested + // (DefaultFileLength), so hydration fails with a size mismatch (actionable cause). + MockGVFSGitObjects mockGVFSGitObjects = this.Repo.GitObjects as MockGVFSGitObjects; + mockGVFSGitObjects.FileLength = MockGVFSGitObjects.DefaultFileLength - 1; + + tester.InvokeGetFileDataCallback(expectedResult: HResult.Pending); + tester.MockVirtualization.WaitForCompletionStatus(); + + MockTracer mockTracker = this.Repo.Context.Tracer as MockTracer; + mockTracker.RelatedErrorEvents.Any( + e => e.Contains("\"BlobHydrationFailureCategory\":\"SizeMismatch\"")).ShouldBeTrue(); + } + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void OnGetFileStreamTagsUnexpectedException() + { + using (WindowsFileSystemVirtualizerTester tester = new WindowsFileSystemVirtualizerTester(this.Repo)) + { + // A non-cancellation, non-GetFileStreamException failure hits the generic catch and + // is tagged Unexpected so it can be triaged separately from known causes. + MockGVFSGitObjects mockGVFSGitObjects = this.Repo.GitObjects as MockGVFSGitObjects; + mockGVFSGitObjects.ThrowOnTryCopyBlobContentStream = true; + + tester.InvokeGetFileDataCallback(expectedResult: HResult.Pending); + tester.MockVirtualization.WaitForCompletionStatus(); + + MockTracer mockTracker = this.Repo.Context.Tracer as MockTracer; + mockTracker.RelatedErrorEvents.Any( + e => e.Contains("\"BlobHydrationFailureCategory\":\"Unexpected\"")).ShouldBeTrue(); + } + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void OnGetFileStreamTagsLocalIO() + { + using (WindowsFileSystemVirtualizerTester tester = new WindowsFileSystemVirtualizerTester(this.Repo)) + { + // Reading the blob content throws IOException while copying to the ProjFS buffer, + // so hydration fails with the LocalIO cause (outside gvfs.exe's control). + MockGVFSGitObjects mockGVFSGitObjects = this.Repo.GitObjects as MockGVFSGitObjects; + mockGVFSGitObjects.ThrowIOExceptionDuringCopy = true; + + tester.InvokeGetFileDataCallback(expectedResult: HResult.Pending); + tester.MockVirtualization.WaitForCompletionStatus(); + + MockTracer mockTracker = this.Repo.Context.Tracer as MockTracer; + mockTracker.RelatedErrorEvents.Any( + e => e.Contains("\"BlobHydrationFailureCategory\":\"LocalIO\"")).ShouldBeTrue(); } }