diff --git a/.github/workflows/build.yaml b/.github/workflows/build.yaml index c21a46e87e..e550568da4 100644 --- a/.github/workflows/build.yaml +++ b/.github/workflows/build.yaml @@ -4,9 +4,9 @@ run-name: ${{ inputs.run_name || 'VFS for Git' }} on: pull_request: - branches: [ master, releases/shipped ] + branches: [ master, releases/shipped, vnext ] push: - branches: [ master, releases/shipped ] + branches: [ master, releases/shipped, vnext ] workflow_dispatch: inputs: git_version: @@ -24,7 +24,7 @@ permissions: checks: read env: - GIT_VERSION: ${{ github.event.inputs.git_version || 'v2.54.0.vfs.0.5' }} + GIT_VERSION: ${{ github.event.inputs.git_version || 'v2.55.0.vfs.0.6' }} jobs: validate: @@ -283,7 +283,7 @@ jobs: - name: Install .NET SDK if: steps.skip.outputs.result != 'true' - uses: actions/setup-dotnet@v5 + uses: actions/setup-dotnet@v6 with: global-json-file: src/global.json diff --git a/GVFS/GVFS.Common/FileSystem/HooksInstaller.cs b/GVFS/GVFS.Common/FileSystem/HooksInstaller.cs index 407918c67d..f43ba508d0 100644 --- a/GVFS/GVFS.Common/FileSystem/HooksInstaller.cs +++ b/GVFS/GVFS.Common/FileSystem/HooksInstaller.cs @@ -2,7 +2,6 @@ using GVFS.Common.Tracing; using System; using System.Collections.Generic; -using System.Diagnostics; using System.IO; using System.Linq; using System.Reflection; @@ -183,7 +182,7 @@ public static bool TryHooksInstallationAction(Action action, out string errorMes { if (retriesLeft == 0) { - errorMessage = re.InnerException.ToString(); + errorMessage = (re.InnerException ?? re).ToString(); return false; } @@ -209,7 +208,7 @@ private static bool TryUpdateHook( return TryUpdateHook(context, hook.Name, installedHookPath, enlistmentHookPath, out errorMessage); } - private static bool TryUpdateHook( + internal static bool TryUpdateHook( GVFSContext context, string hookName, string installedHookPath, @@ -228,47 +227,66 @@ private static bool TryUpdateHook( { copyHook = true; - EventMetadata metadata = new EventMetadata(); - metadata.Add("Area", "Mount"); - metadata.Add(nameof(enlistmentHookPath), enlistmentHookPath); - metadata.Add(nameof(installedHookPath), installedHookPath); - metadata.Add(TracingConstants.MessageKey.WarningMessage, hookName + " not found in enlistment, copying from installation folder"); - context.Tracer.RelatedWarning(hookName + " MissingFromEnlistment", metadata); + EventMetadata metadata = CreateHookEventMetadata(installedHookPath, enlistmentHookPath); + metadata.Add("HookUpdateResult", "MissingFromEnlistment"); + context.Tracer.RelatedWarning(metadata, hookName + " not found in enlistment, copying from installation folder", Keywords.Telemetry); } else { try { - FileVersionInfo enlistmentVersion = FileVersionInfo.GetVersionInfo(enlistmentHookPath); - FileVersionInfo installedVersion = FileVersionInfo.GetVersionInfo(installedHookPath); - copyHook = enlistmentVersion.FileVersion != installedVersion.FileVersion; + // Compare the enlistment hook against the installed hook by FileVersion. + // These native hook binaries embed their GVFS version in the PE version + // resource, so the version differs only when a GVFS upgrade changed the + // hook - which is rare (roughly monthly) compared to daily mounts. So the + // common daily mount does no copy, and a copy happens on the first mount + // after an upgrade. + copyHook = !HookVersionsMatch(context, installedHookPath, enlistmentHookPath); } catch (Exception e) { - EventMetadata metadata = new EventMetadata(); - metadata.Add("Area", "Mount"); - metadata.Add(nameof(enlistmentHookPath), enlistmentHookPath); - metadata.Add(nameof(installedHookPath), installedHookPath); + // Reading the version opens the hook files, either of which can be + // transiently locked (open handle, AV scan) - the same failure class the + // copy path is hardened against. Do not fail the mount here: assume the + // enlistment hook may be stale, set copyHook so the resilient copy path + // runs (retry with backoff, then the "already matches" recheck). If a lock + // persists, that path reports the error after exhausting retries. + EventMetadata metadata = CreateHookEventMetadata(installedHookPath, enlistmentHookPath); metadata.Add("Exception", e.ToString()); - context.Tracer.RelatedError(metadata, "Failed to compare " + hookName + " version"); - errorMessage = "Error comparing " + hookName + " versions. " + ConsoleHelper.GetGVFSLogMessage(context.Enlistment.WorkingDirectoryRoot); - return false; + metadata.Add("HookUpdateResult", "CompareFailed"); + context.Tracer.RelatedWarning(metadata, "Failed to compare " + hookName + " version; will attempt to refresh the hook", Keywords.Telemetry); + copyHook = true; } } if (copyHook) { - try + // Retry the copy with backoff, matching the clone-time InstallHooks path. + // The enlistment hook can be transiently locked (open handle, AV scan), + // in which case the rename fails with a RetryableException wrapping + // ERROR_ACCESS_DENIED. A transient lock must not be fatal to the mount. + if (!TryHooksInstallationAction(() => CopyHook(context, installedHookPath, enlistmentHookPath), out string copyError)) { - CopyHook(context, installedHookPath, enlistmentHookPath); - } - catch (Exception e) - { - EventMetadata metadata = new EventMetadata(); - metadata.Add("Area", "Mount"); - metadata.Add(nameof(enlistmentHookPath), enlistmentHookPath); - metadata.Add(nameof(installedHookPath), installedHookPath); - metadata.Add("Exception", e.ToString()); + // The copy could not complete after retries. If the enlistment hook + // already matches the installed one, the binary is correct and the + // lock is harmless - treat it as success rather than killing the mount. + if (HookExistsAndVersionMatches(context, installedHookPath, enlistmentHookPath)) + { + EventMetadata alreadyCorrect = CreateHookEventMetadata(installedHookPath, enlistmentHookPath); + alreadyCorrect.Add("CopyError", copyError); + alreadyCorrect.Add("HookUpdateResult", "LockedButAlreadyCorrect"); + context.Tracer.RelatedWarning( + alreadyCorrect, + hookName + " could not be re-copied but already matches the installed hook; continuing", + Keywords.Telemetry); + + errorMessage = null; + return true; + } + + EventMetadata metadata = CreateHookEventMetadata(installedHookPath, enlistmentHookPath); + metadata.Add("Exception", copyError); + metadata.Add("HookUpdateResult", "CopyFailed"); context.Tracer.RelatedError(metadata, "Failed to copy " + hookName + " to enlistment"); errorMessage = "Error copying " + hookName + " to enlistment. " + ConsoleHelper.GetGVFSLogMessage(context.Enlistment.WorkingDirectoryRoot); return false; @@ -279,6 +297,55 @@ private static bool TryUpdateHook( return true; } + /// + /// Seeds an with the fields common to every mount-time + /// hook-update outcome. Callers add an outcome-specific "HookUpdateResult" value (and + /// any exception detail) so all outcomes are queryable by that field. + /// + private static EventMetadata CreateHookEventMetadata(string installedHookPath, string enlistmentHookPath) + { + EventMetadata metadata = new EventMetadata(); + metadata.Add("Area", "Mount"); + metadata.Add(nameof(enlistmentHookPath), enlistmentHookPath); + metadata.Add(nameof(installedHookPath), installedHookPath); + return metadata; + } + + /// + /// Returns true only when both files report the same, non-empty FileVersion. An + /// absent/empty version is treated as "cannot confirm identical" (not a match), so the + /// resilient copy path runs. Otherwise two version-less binaries would compare equal + /// (string.Equals(null, null) == true) and the hook would never be refreshed, silently + /// defeating the self-heal this comparison provides. Both files must exist. + /// + private static bool HookVersionsMatch(GVFSContext context, string installedHookPath, string enlistmentHookPath) + { + string installedVersion = context.FileSystem.GetFileVersion(installedHookPath); + string enlistmentVersion = context.FileSystem.GetFileVersion(enlistmentHookPath); + + return !string.IsNullOrEmpty(installedVersion) + && string.Equals(installedVersion, enlistmentVersion, StringComparison.OrdinalIgnoreCase); + } + + /// + /// Returns true only when the enlistment hook exists and its FileVersion matches the + /// installed hook. Any failure to read or compare (for example, the file is exclusively + /// locked) is treated as "does not match" so callers do not mistake an unknown state + /// for success. + /// + private static bool HookExistsAndVersionMatches(GVFSContext context, string installedHookPath, string enlistmentHookPath) + { + try + { + return context.FileSystem.FileExists(enlistmentHookPath) + && HookVersionsMatch(context, installedHookPath, enlistmentHookPath); + } + catch (Exception) + { + return false; + } + } + public class HooksConfigurationException : Exception { public HooksConfigurationException(string message) diff --git a/GVFS/GVFS.Common/FileSystem/PhysicalFileSystem.cs b/GVFS/GVFS.Common/FileSystem/PhysicalFileSystem.cs index 3b1ebe2675..b1f7bd97ac 100644 --- a/GVFS/GVFS.Common/FileSystem/PhysicalFileSystem.cs +++ b/GVFS/GVFS.Common/FileSystem/PhysicalFileSystem.cs @@ -258,19 +258,9 @@ public virtual string[] GetFiles(string directoryPath, string mask) return Directory.GetFiles(directoryPath, mask); } - public virtual FileVersionInfo GetVersionInfo(string path) + public virtual string GetFileVersion(string path) { - return FileVersionInfo.GetVersionInfo(path); - } - - public virtual bool FileVersionsMatch(FileVersionInfo versionInfo1, FileVersionInfo versionInfo2) - { - return versionInfo1.FileVersion == versionInfo2.FileVersion; - } - - public virtual bool ProductVersionsMatch(FileVersionInfo versionInfo1, FileVersionInfo versionInfo2) - { - return versionInfo1.ProductVersion == versionInfo2.ProductVersion; + return FileVersionInfo.GetVersionInfo(path).FileVersion; } public bool TryWriteTempFileAndRename(string destinationPath, string contents, out Exception handledException) @@ -310,7 +300,7 @@ public bool TryWriteTempFileAndRename(string destinationPath, string contents, o } } - public bool TryCopyToTempFileAndRename(string sourcePath, string destinationPath, out Exception handledException) + public virtual bool TryCopyToTempFileAndRename(string sourcePath, string destinationPath, out Exception handledException) { handledException = null; string tempFilePath = destinationPath + ".temp"; diff --git a/GVFS/GVFS.Common/Git/GVFSGitObjects.cs b/GVFS/GVFS.Common/Git/GVFSGitObjects.cs index b9044b2be4..b232e7b74c 100644 --- a/GVFS/GVFS.Common/Git/GVFSGitObjects.cs +++ b/GVFS/GVFS.Common/Git/GVFSGitObjects.cs @@ -3,6 +3,7 @@ using System; using System.Collections.Concurrent; using System.Collections.Generic; +using System.ComponentModel; using System.IO; using System.Net; using System.Threading; @@ -33,14 +34,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 +85,44 @@ 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()); + + // A RetryableException wraps its real cause in InnerException, so inspect the + // inner exception rather than the RetryableException type. On this branch the + // exception arrives from Context.Repository.TryCopyBlobContentStream - typically + // StreamUtil wrapping an IOException while reading a corrupt/truncated local + // loose object (UnauthorizedAccessException/Win32Exception are treated the same + // as they belong to the local disk/IO family). Without this unwrap every + // RetryableException - the single largest hydration-failure bucket in the field - + // is misattributed to NetworkUnavailable even when the cause is local disk/IO. A + // stream-read IOException can still originate in the download layer, but we cannot + // tell where it came from, so it is bucketed as local IO. + Exception rootError = (errorArgs.Error as RetryableException)?.InnerException ?? errorArgs.Error; + category = rootError is IOException || rootError is UnauthorizedAccessException || rootError is Win32Exception + ? 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 +145,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.FunctionalTests/Tests/EnlistmentPerFixture/HealthTests.cs b/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/HealthTests.cs index 3e4d7ec847..e469991750 100644 --- a/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/HealthTests.cs +++ b/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/HealthTests.cs @@ -262,9 +262,10 @@ private void ValidateSubDirectoryHealth(List outputLines, List s private void ValidateEnlistmentStatus(string outputLine, string statusMessage) { - // Regex to extract the status message for the enlistment - // "Repository status: " - Match lineMatch = Regex.Match(outputLine, @"^Repository status:\s*(.*)$"); + // Regex to extract the status message for the enlistment. The verb prints + // "Repository status: " when the calculation covers the whole enlistment, + // and "Directory status (): " when scoped to a subdirectory. + Match lineMatch = Regex.Match(outputLine, @"^(?:Repository status|Directory status \([^)]*\)):\s*(.*)$"); string outputtedStatusMessage = lineMatch.Groups[1].Value; diff --git a/GVFS/GVFS.Platform.Windows/WindowsFileSystemVirtualizer.cs b/GVFS/GVFS.Platform.Windows/WindowsFileSystemVirtualizer.cs index a4bea90680..7a6bad6f24 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/CommandLine/HooksInstallerMountUpdateTests.cs b/GVFS/GVFS.UnitTests/CommandLine/HooksInstallerMountUpdateTests.cs new file mode 100644 index 0000000000..f01ffa5f26 --- /dev/null +++ b/GVFS/GVFS.UnitTests/CommandLine/HooksInstallerMountUpdateTests.cs @@ -0,0 +1,321 @@ +using GVFS.Common; +using GVFS.Common.FileSystem; +using GVFS.Tests.Should; +using GVFS.UnitTests.Mock.Common; +using GVFS.UnitTests.Mock.FileSystem; +using NUnit.Framework; +using System; +using System.Collections.Generic; +using System.ComponentModel; +using System.IO; + +namespace GVFS.UnitTests.CommandLine +{ + [TestFixture] + public class HooksInstallerMountUpdateTests + { + private const string HookName = "GVFS.ReadObjectHook"; + private const string RootPath = "mock:"; + private static readonly string InstalledDir = Path.Combine(RootPath, "installed"); + private static readonly string EnlistmentDir = Path.Combine(RootPath, "enlistment"); + private static readonly string InstalledHookPath = Path.Combine(InstalledDir, "GVFS.ReadObjectHook.exe"); + private static readonly string EnlistmentHookPath = Path.Combine(EnlistmentDir, "GVFS.ReadObjectHook.exe"); + + private const string InstalledContent = "installed-hook-binary-v2"; + private const string OldEnlistmentContent = "old-hook-binary-v1"; + + [TestCase] + public void IdenticalHookIsNotCopied() + { + CopyControllableFileSystem fileSystem = this.CreateFileSystem(enlistmentContent: InstalledContent); + GVFSContext context = this.CreateContext(fileSystem); + + bool result = HooksInstaller.TryUpdateHook(context, HookName, InstalledHookPath, EnlistmentHookPath, out string errorMessage); + + result.ShouldBeTrue(errorMessage); + errorMessage.ShouldBeNull(); + fileSystem.CopyAttempts.ShouldEqual(0, "Identical hooks must not be re-copied"); + } + + [TestCase] + public void DifferentHookIsCopiedOnce() + { + CopyControllableFileSystem fileSystem = this.CreateFileSystem(enlistmentContent: OldEnlistmentContent); + GVFSContext context = this.CreateContext(fileSystem); + + bool result = HooksInstaller.TryUpdateHook(context, HookName, InstalledHookPath, EnlistmentHookPath, out string errorMessage); + + result.ShouldBeTrue(errorMessage); + errorMessage.ShouldBeNull(); + fileSystem.CopyAttempts.ShouldEqual(1); + fileSystem.ReadAllText(EnlistmentHookPath).ShouldEqual(InstalledContent); + } + + [TestCase] + public void MissingHookIsCopied() + { + CopyControllableFileSystem fileSystem = this.CreateFileSystem(enlistmentContent: null); + GVFSContext context = this.CreateContext(fileSystem); + + bool result = HooksInstaller.TryUpdateHook(context, HookName, InstalledHookPath, EnlistmentHookPath, out string errorMessage); + + result.ShouldBeTrue(errorMessage); + errorMessage.ShouldBeNull(); + fileSystem.CopyAttempts.ShouldEqual(1); + fileSystem.ReadAllText(EnlistmentHookPath).ShouldEqual(InstalledContent); + } + + [TestCase] + public void HookIsCopiedWhenVersionDiffersEvenIfContentIsIdentical() + { + // Production compares FileVersion, not content. If the version differs, the hook + // must be refreshed even when the bytes happen to match. The double models version + // independently of content so this case is representable. + CopyControllableFileSystem fileSystem = this.CreateFileSystem(enlistmentContent: InstalledContent); + fileSystem.SetFileVersion(InstalledHookPath, "2.0.0.0"); + fileSystem.SetFileVersion(EnlistmentHookPath, "1.0.0.0"); + GVFSContext context = this.CreateContext(fileSystem); + + bool result = HooksInstaller.TryUpdateHook(context, HookName, InstalledHookPath, EnlistmentHookPath, out string errorMessage); + + result.ShouldBeTrue(errorMessage); + errorMessage.ShouldBeNull(); + fileSystem.CopyAttempts.ShouldEqual(1, "A version difference must trigger a copy even when content matches"); + fileSystem.GetFileVersion(EnlistmentHookPath).ShouldEqual("2.0.0.0", "The copied hook must carry the installed version"); + } + + [TestCase] + public void HookIsNotCopiedWhenVersionMatchesEvenIfContentDiffers() + { + // Production compares FileVersion, not content. If the version matches, no copy + // happens even when the bytes differ. This pins that the comparison is by version. + CopyControllableFileSystem fileSystem = this.CreateFileSystem(enlistmentContent: OldEnlistmentContent); + fileSystem.SetFileVersion(InstalledHookPath, "2.0.0.0"); + fileSystem.SetFileVersion(EnlistmentHookPath, "2.0.0.0"); + GVFSContext context = this.CreateContext(fileSystem); + + bool result = HooksInstaller.TryUpdateHook(context, HookName, InstalledHookPath, EnlistmentHookPath, out string errorMessage); + + result.ShouldBeTrue(errorMessage); + errorMessage.ShouldBeNull(); + fileSystem.CopyAttempts.ShouldEqual(0, "A matching version must not trigger a copy even when content differs"); + } + + [TestCase] + public void HookIsCopiedWhenBothVersionsAreNull() + { + // GetFileVersion returns null for a binary with no version resource. Two null + // versions must NOT be treated as identical (string.Equals(null, null) == true); + // otherwise a version-less hook would never be refreshed. The hook must be copied. + CopyControllableFileSystem fileSystem = this.CreateFileSystem(enlistmentContent: InstalledContent); + fileSystem.SetFileVersion(InstalledHookPath, null); + fileSystem.SetFileVersion(EnlistmentHookPath, null); + GVFSContext context = this.CreateContext(fileSystem); + + bool result = HooksInstaller.TryUpdateHook(context, HookName, InstalledHookPath, EnlistmentHookPath, out string errorMessage); + + result.ShouldBeTrue(errorMessage); + errorMessage.ShouldBeNull(); + fileSystem.CopyAttempts.ShouldEqual(1, "An unknown (null) version must force a copy rather than be assumed identical"); + } + + [TestCase] + public void TransientCopyFailureIsRetriedAndSucceeds() + { + CopyControllableFileSystem fileSystem = this.CreateFileSystem(enlistmentContent: OldEnlistmentContent); + fileSystem.FailCopyCount = 2; + GVFSContext context = this.CreateContext(fileSystem); + + bool result = HooksInstaller.TryUpdateHook(context, HookName, InstalledHookPath, EnlistmentHookPath, out string errorMessage); + + result.ShouldBeTrue(errorMessage); + errorMessage.ShouldBeNull(); + fileSystem.CopyAttempts.ShouldEqual(3, "The copy must be retried past two transient failures"); + fileSystem.ReadAllText(EnlistmentHookPath).ShouldEqual(InstalledContent); + } + + [TestCase] + public void LockedButAlreadyCorrectHookDoesNotFailMount() + { + CopyControllableFileSystem fileSystem = this.CreateFileSystem(enlistmentContent: OldEnlistmentContent); + fileSystem.AlwaysFailCopy = true; + fileSystem.WriteCorrectDestinationOnFailure = true; + MockTracer tracer = new MockTracer(); + GVFSContext context = this.CreateContext(fileSystem, tracer); + + bool result = HooksInstaller.TryUpdateHook(context, HookName, InstalledHookPath, EnlistmentHookPath, out string errorMessage); + + result.ShouldBeTrue("A locked hook that already matches the installed hook must not fail the mount"); + errorMessage.ShouldBeNull(); + tracer.RelatedErrorEvents.Count.ShouldEqual(0, "A locked-but-correct hook must not log an error"); + } + + [TestCase] + public void CompareFailureDoesNotHardFailMountAndRefreshesHook() + { + // The enlistment hook is transiently locked such that reading its version to + // compare throws. The mount must not hard-fail on the compare; it must fall + // through to the resilient copy path and refresh the hook. + CopyControllableFileSystem fileSystem = this.CreateFileSystem(enlistmentContent: OldEnlistmentContent); + fileSystem.ThrowOnGetVersionPath = EnlistmentHookPath; + MockTracer tracer = new MockTracer(); + GVFSContext context = this.CreateContext(fileSystem, tracer); + + bool result = HooksInstaller.TryUpdateHook(context, HookName, InstalledHookPath, EnlistmentHookPath, out string errorMessage); + + result.ShouldBeTrue(errorMessage); + errorMessage.ShouldBeNull(); + tracer.RelatedErrorEvents.Count.ShouldEqual(0, "A compare failure must not be fatal to the mount"); + fileSystem.CopyAttempts.ShouldBeAtLeast(1, "The hook must be refreshed after a compare failure"); + fileSystem.ReadAllText(EnlistmentHookPath).ShouldEqual(InstalledContent); + } + + [TestCase] + public void MissingInstalledHookFailsWithoutCopying() + { + CopyControllableFileSystem fileSystem = this.CreateFileSystem(enlistmentContent: OldEnlistmentContent, includeInstalled: false); + GVFSContext context = this.CreateContext(fileSystem); + + bool result = HooksInstaller.TryUpdateHook(context, HookName, InstalledHookPath, EnlistmentHookPath, out string errorMessage); + + result.ShouldBeFalse(); + errorMessage.ShouldNotBeNull(); + errorMessage.ShouldContain("cannot be found"); + fileSystem.CopyAttempts.ShouldEqual(0, "A missing installed hook must not trigger a copy"); + } + + [TestCase] + public void PersistentCopyFailureFailsMount() + { + CopyControllableFileSystem fileSystem = this.CreateFileSystem(enlistmentContent: OldEnlistmentContent); + fileSystem.AlwaysFailCopy = true; + MockTracer tracer = new MockTracer(); + GVFSContext context = this.CreateContext(fileSystem, tracer); + + bool result = HooksInstaller.TryUpdateHook(context, HookName, InstalledHookPath, EnlistmentHookPath, out string errorMessage); + + result.ShouldBeFalse(); + errorMessage.ShouldNotBeNull(); + errorMessage.ShouldContain(HookName); + tracer.RelatedErrorEvents.Count.ShouldBeAtLeast(1); + } + + private CopyControllableFileSystem CreateFileSystem(string enlistmentContent, bool includeInstalled = true) + { + MockDirectory root = new MockDirectory( + RootPath, + new[] + { + new MockDirectory(InstalledDir, folders: null, files: null), + new MockDirectory(EnlistmentDir, folders: null, files: null), + }, + files: null); + + CopyControllableFileSystem fileSystem = new CopyControllableFileSystem(root); + if (includeInstalled) + { + fileSystem.WriteAllText(InstalledHookPath, InstalledContent); + } + + if (enlistmentContent != null) + { + fileSystem.WriteAllText(EnlistmentHookPath, enlistmentContent); + } + + return fileSystem; + } + + private GVFSContext CreateContext(CopyControllableFileSystem fileSystem, MockTracer tracer = null) + { + return new GVFSContext( + tracer ?? new MockTracer(), + fileSystem, + repository: null, + new MockGVFSEnlistment()); + } + + private sealed class CopyControllableFileSystem : MockFileSystem + { + private readonly Dictionary explicitVersions = new Dictionary(StringComparer.OrdinalIgnoreCase); + + public CopyControllableFileSystem(MockDirectory rootDirectory) + : base(rootDirectory) + { + } + + public int CopyAttempts { get; private set; } + + public int FailCopyCount { get; set; } + + public bool AlwaysFailCopy { get; set; } + + public bool WriteCorrectDestinationOnFailure { get; set; } + + public string ThrowOnGetVersionPath { get; set; } + + /// + /// Pins a path's FileVersion independently of its content, so tests can model the + /// real decoupling between a PE version resource and file bytes (including a null + /// version). A path with no explicit version falls back to its stored text, which + /// keeps the common "version tracks content" tests simple. + /// + public void SetFileVersion(string path, string version) + { + this.explicitVersions[path] = version; + } + + public override string GetFileVersion(string path) + { + if (this.ThrowOnGetVersionPath != null && path == this.ThrowOnGetVersionPath) + { + throw new IOException("The process cannot access the file because it is being used by another process."); + } + + if (this.explicitVersions.TryGetValue(path, out string version)) + { + return version; + } + + return this.ReadAllText(path); + } + + public override bool TryCopyToTempFileAndRename(string sourcePath, string destinationPath, out Exception handledException) + { + this.CopyAttempts++; + + if (this.AlwaysFailCopy || this.CopyAttempts <= this.FailCopyCount) + { + if (this.WriteCorrectDestinationOnFailure) + { + // Simulate another writer (or the lock holder) leaving the correct + // binary in place even though our rename could not complete. + this.PropagateHook(sourcePath, destinationPath); + } + + handledException = new Win32Exception(5, "Access is denied"); + return false; + } + + this.PropagateHook(sourcePath, destinationPath); + handledException = null; + return true; + } + + // Model an on-disk copy: the destination takes the source's content AND its + // version, so the two converge exactly as they would after a real file copy. + private void PropagateHook(string sourcePath, string destinationPath) + { + this.WriteAllText(destinationPath, this.ReadAllText(sourcePath)); + + if (this.explicitVersions.TryGetValue(sourcePath, out string sourceVersion)) + { + this.explicitVersions[destinationPath] = sourceVersion; + } + else + { + this.explicitVersions.Remove(destinationPath); + } + } + } + } +} diff --git a/GVFS/GVFS.UnitTests/Git/GVFSGitObjectsTests.cs b/GVFS/GVFS.UnitTests/Git/GVFSGitObjectsTests.cs index caa23da244..205d2b4de6 100644 --- a/GVFS/GVFS.UnitTests/Git/GVFSGitObjectsTests.cs +++ b/GVFS/GVFS.UnitTests/Git/GVFSGitObjectsTests.cs @@ -1,6 +1,7 @@ using GVFS.Common; using GVFS.Common.Git; using GVFS.Common.Http; +using GVFS.Common.Tracing; using GVFS.Tests.Should; using GVFS.UnitTests.Category; using GVFS.UnitTests.Mock; @@ -11,7 +12,9 @@ using System; using System.Collections.Generic; using System.IO; +using System.Linq; using System.Net; +using System.Net.Http; using System.Reflection; using System.Threading; @@ -30,6 +33,24 @@ public class GVFSGitObjectsTests 0x48, 0xE4, 0x02, 0x00, 0x0E, 0x64, 0x02, 0x5D }; + [SetUp] + public void SetUp() + { + // These tests deliberately drive the retrier to failure, which records failures on the + // process-global RetryCircuitBreaker. Reset it before each test so an accumulation of + // failures from earlier tests cannot open the circuit and fast-fail a later test with a + // circuit-open RetryableException (which would otherwise be mis-read as its cause). + RetryCircuitBreaker.Reset(); + } + + [TearDown] + public void TearDown() + { + // Reset on exit too, so this fixture cannot leave the process-global circuit dirty for a + // later breaker-sensitive fixture (NUnit does not guarantee cross-fixture ordering). + RetryCircuitBreaker.Reset(); + } + [TestCase] [Category(CategoryConstants.ExceptionExpected)] public void CatchesFileNotFoundAfterFileDeleted() @@ -56,11 +77,202 @@ 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] + [Category(CategoryConstants.ExceptionExpected)] + public void TerminalBlobHydrationFailureUnwrapsRetryableLocalIOException() + { + // A RetryableException reaches this branch from Context.Repository.TryCopyBlobContentStream - + // e.g. StreamUtil wrapping an IOException while reading a corrupt/truncated local loose + // object. Its inner cause must be attributed to LocalIO, not NetworkUnavailable. Regression + // guard for the RetryableException.InnerException unwrap in the failure categorization. + this.AssertRetryableCauseMapsToCategory( + new RetryableException("wrapped local IO failure", new IOException("The device is not ready.")), + GVFSGitObjects.BlobHydrationFailureCategory.LocalIO); + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void TerminalBlobHydrationFailureUnwrapsRetryableUnauthorizedAccessAsLocalIO() + { + // UnauthorizedAccessException belongs to the local disk/IO family and must map to LocalIO + // after the InnerException unwrap. + this.AssertRetryableCauseMapsToCategory( + new RetryableException("wrapped local access failure", new UnauthorizedAccessException("Access to the path is denied.")), + GVFSGitObjects.BlobHydrationFailureCategory.LocalIO); + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void TerminalBlobHydrationFailureUnwrapsRetryableWin32AsLocalIO() + { + // Win32Exception (here a disk-full native error) belongs to the local disk/IO family and + // must map to LocalIO after the InnerException unwrap. + this.AssertRetryableCauseMapsToCategory( + new RetryableException("wrapped local Win32 failure", new System.ComponentModel.Win32Exception(112)), + GVFSGitObjects.BlobHydrationFailureCategory.LocalIO); + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void TerminalBlobHydrationFailureKeepsRetryableNonLocalInnerAsNetworkUnavailable() + { + // A RetryableException whose inner cause is NOT a local disk/IO type (here an + // HttpRequestException) must stay NetworkUnavailable - this proves the unwrap does not + // over-attribute to LocalIO. + this.AssertRetryableCauseMapsToCategory( + new RetryableException("wrapped network failure", new HttpRequestException("Connection refused.")), + GVFSGitObjects.BlobHydrationFailureCategory.NetworkUnavailable); + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void TerminalBlobHydrationFailureTagsRetryableNetworkAsNetworkUnavailable() + { + // A RetryableException with no inner exception (a bare network-flakiness signal, e.g. a + // null download stream) is genuinely outside gvfs.exe's control, so it stays + // NetworkUnavailable after the InnerException unwrap. + this.AssertRetryableCauseMapsToCategory( + new RetryableException("Stream is null (this could be a result of network flakiness), retrying."), + GVFSGitObjects.BlobHydrationFailureCategory.NetworkUnavailable); + } + + private void AssertRetryableCauseMapsToCategory(RetryableException thrownException, GVFSGitObjects.BlobHydrationFailureCategory expected) + { + GitRepo throwingRepo = new ThrowingGitRepo(new MockTracer(), thrownException); + MockHttpGitObjects httpObjects = new MockHttpGitObjects(); + GVFSGitObjects dut = this.CreateTestableGVFSGitObjects(httpObjects, throwingRepo, 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(expected); + string terminalError = tracer.RelatedErrorEvents.First(e => e.Contains("Failed to provide blob contents")); + terminalError.ShouldContain("\"BlobHydrationFailureCategory\":\"" + expected + "\""); + } + [TestCase] public void SucceedsForNormalLookingLooseObjectDownloads() { @@ -541,12 +753,30 @@ 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, GitRepo repo, out MockTracer tracer) + { + MockTracer localTracer = new MockTracer(); + tracer = localTracer; + GVFSEnlistment enlistment = new GVFSEnlistment(TestEnlistmentRoot, "https://fakeRepoUrl", "fakeGitBinPath", authentication: null); + enlistment.InitializeCachePathsFromKey(TestLocalCacheRoot, TestObjectRoot); + + GVFSContext context = new GVFSContext(localTracer, new MockFileSystemWithCallbacks(), repo, enlistment); + GVFSGitObjects dut = new UnsafeGVFSGitObjects(context, httpObjects); + return dut; + } + + 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 +795,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 +827,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)) { @@ -624,6 +872,22 @@ public UnsafeGVFSGitObjects(GVFSContext context, GitObjectsHttpRequestor objectR } } + private sealed class ThrowingGitRepo : GitRepo + { + private readonly Exception toThrow; + + public ThrowingGitRepo(ITracer tracer, Exception toThrow) + : base(tracer) + { + this.toThrow = toThrow; + } + + public override bool TryCopyBlobContentStream(string blobSha, Action writeAction) + { + throw this.toThrow; + } + } + private class CoalescingTestHttpGitObjects : GitObjectsHttpRequestor { private readonly byte[] objectContents; diff --git a/GVFS/GVFS.UnitTests/Mock/FileSystem/MockFileSystem.cs b/GVFS/GVFS.UnitTests/Mock/FileSystem/MockFileSystem.cs index 77b4783a1b..8f039a7dc3 100644 --- a/GVFS/GVFS.UnitTests/Mock/FileSystem/MockFileSystem.cs +++ b/GVFS/GVFS.UnitTests/Mock/FileSystem/MockFileSystem.cs @@ -5,7 +5,6 @@ using Microsoft.Win32.SafeHandles; using System; using System.Collections.Generic; -using System.Diagnostics; using System.IO; namespace GVFS.UnitTests.Mock.FileSystem @@ -338,21 +337,6 @@ public override string[] GetFiles(string directoryPath, string mask) return files.ToArray(); } - public override FileVersionInfo GetVersionInfo(string path) - { - throw new NotImplementedException(); - } - - public override bool FileVersionsMatch(FileVersionInfo versionInfo1, FileVersionInfo versionInfo2) - { - throw new NotImplementedException(); - } - - public override bool ProductVersionsMatch(FileVersionInfo versionInfo1, FileVersionInfo versionInfo2) - { - throw new NotImplementedException(); - } - private Stream CreateAndOpenFileStream(string path) { MockFile file = this.RootDirectory.CreateFile(path); diff --git a/GVFS/GVFS.UnitTests/Mock/Git/MockGVFSGitObjects.cs b/GVFS/GVFS.UnitTests/Mock/Git/MockGVFSGitObjects.cs index b95984ecce..bb34332875 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 c2d96a446b..bfd4a0e094 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(); } } diff --git a/GVFS/GVFS/CommandLine/HealthVerb.cs b/GVFS/GVFS/CommandLine/HealthVerb.cs index 9f9ed21091..8bb453ac9c 100644 --- a/GVFS/GVFS/CommandLine/HealthVerb.cs +++ b/GVFS/GVFS/CommandLine/HealthVerb.cs @@ -208,7 +208,23 @@ private void PrintOutput(EnlistmentHealthData enlistmentHealthData) bool healthyRepo = (enlistmentHealthData.PlaceholderPercentage + enlistmentHealthData.ModifiedPathsPercentage) < MaximumHealthyHydration; - this.Output.WriteLine("\nRepository status: " + (healthyRepo ? "OK" : "Highly Hydrated")); + // Only label the summary as "Repository status" when the calculation actually covered + // the whole enlistment. When the user scoped the check to a subdirectory (via -d or by + // running from a subdirectory of the enlistment) the number describes only that subtree, + // so label it accordingly to avoid falsely reporting the repository as highly hydrated. + bool isWholeRepo = string.IsNullOrEmpty(enlistmentHealthData.TargetDirectory) + || enlistmentHealthData.TargetDirectory == GVFSConstants.GitPathSeparatorString; + + string statusLabel = isWholeRepo + ? "Repository status" + : "Directory status (" + enlistmentHealthData.TargetDirectory.TrimEnd(GVFSConstants.GitPathSeparator) + ")"; + + this.Output.WriteLine("\n" + statusLabel + ": " + (healthyRepo ? "OK" : "Highly Hydrated")); + + if (!isWholeRepo) + { + this.Output.WriteLine("To see the full repository status, switch to the root of the repository and re-run 'gvfs health'."); + } } ///