diff --git a/GVFS/GVFS.Common/GVFSEnlistment.cs b/GVFS/GVFS.Common/GVFSEnlistment.cs index 7cd441aadb..51779cb385 100644 --- a/GVFS/GVFS.Common/GVFSEnlistment.cs +++ b/GVFS/GVFS.Common/GVFSEnlistment.cs @@ -281,7 +281,9 @@ public static bool WaitUntilMounted( } else if (getStatusResponse.MountStatus == NamedPipeMessages.GetStatus.MountFailed) { - errorMessage = string.Format("Failed to mount at {0}", enlistmentRoot); + errorMessage = !string.IsNullOrWhiteSpace(getStatusResponse.MountError) + ? getStatusResponse.MountError + : string.Format("Failed to mount at {0}", enlistmentRoot); tracer.RelatedError($"{nameof(WaitUntilMounted)}: Mount failed: {errorMessage}"); return false; } diff --git a/GVFS/GVFS.Common/NamedPipes/MountFailureReporter.cs b/GVFS/GVFS.Common/NamedPipes/MountFailureReporter.cs new file mode 100644 index 0000000000..07d417059d --- /dev/null +++ b/GVFS/GVFS.Common/NamedPipes/MountFailureReporter.cs @@ -0,0 +1,226 @@ +using GVFS.Common.Tracing; +using System; +using System.Threading; + +namespace GVFS.Common.NamedPipes +{ + /// + /// The result of a thread trying to take ownership of the mount-failure path. + /// + public enum MountFailureOwnership + { + /// + /// The calling thread now owns reporting and must drive it to process exit. + /// + Owner, + + /// + /// The calling thread already owned reporting and has re-entered, because + /// something threw while it was reporting and an outer catch block called back + /// in. It must not wait again: it would block forever on a signal that it is + /// itself responsible for observing. + /// + Reentrant, + + /// + /// Another thread owns reporting and will exit the process. The calling thread + /// must not continue with a half-initialized mount. + /// + NotOwner, + } + + /// + /// Server half of the mount-failure handshake: keeps a failed mount process alive + /// just long enough for a client to read the reason over the named pipe. + /// + /// + /// Without this, the mount process sets MountFailed and exits immediately. + /// The client polls GetStatus every 100ms, so it usually loses the race, the pipe + /// breaks mid-request, and the user sees a transport error instead of the cause. + /// + /// The wait is deliberately short. Until the process exits it still holds the mount + /// lock and the named pipe, so a longer wait delays the user's next mount attempt. + /// + /// + /// This type owns only the handshake state. Process-exit policy stays with the + /// caller. The client half of the same protocol is + /// . + /// + /// + public sealed class MountFailureReporter : IDisposable + { + /// + /// Cap on how long to wait once a client is known to be polling. + /// + internal const int DefaultReportTimeoutMs = 2000; + + /// + /// Cap used when no client has received a status yet. It only has to cover the + /// gap between the pipe opening and the client's first poll. + /// + internal const int DefaultNoClientTimeoutMs = 500; + + /// + /// Grace period after a client reads the failure. Any client can satisfy the + /// wait, and it is not necessarily the one that is mounting -- a concurrent + /// "gvfs status" polls the same pipe. Keeping this above the client's 100ms poll + /// interval means the mounting client still gets its answer on its next poll. + /// + internal const int DefaultDrainMs = 150; + + private readonly ITracer tracer; + private readonly int reportTimeoutMs; + private readonly int noClientTimeoutMs; + private readonly int drainMs; + private readonly ManualResetEvent failureReported; + + private volatile string failureMessage; + private volatile bool namedPipeReady; + private volatile bool clientReceivedStatus; + + // 0 means no thread owns the failure path yet. + private int owningThreadId; + + public MountFailureReporter(ITracer tracer) + : this(tracer, DefaultReportTimeoutMs, DefaultNoClientTimeoutMs, DefaultDrainMs) + { + } + + /// + /// Test constructor. Lets unit tests use short timeouts so they do not pay the + /// production waits. + /// + internal MountFailureReporter(ITracer tracer, int reportTimeoutMs, int noClientTimeoutMs, int drainMs) + { + this.tracer = tracer; + this.reportTimeoutMs = reportTimeoutMs; + this.noClientTimeoutMs = noClientTimeoutMs; + this.drainMs = drainMs; + this.failureReported = new ManualResetEvent(false); + } + + /// + /// The reason the mount failed, or null if the mount has not failed. Sent to the + /// client in the GetStatus response. + /// + public string FailureMessage + { + get { return this.failureMessage; } + } + + /// + /// Formats a failure message without letting the formatting itself throw. + /// + /// + /// Callers pass messages built from external text (exception strings, server + /// responses) that can contain unbalanced braces. A FormatException here would + /// mask the failure being reported, so fall back to the unformatted string. + /// + public static string FormatFailure(string error, object[] args) + { + if (args == null || args.Length == 0) + { + return error; + } + + try + { + return string.Format(error, args); + } + catch (FormatException) + { + return error; + } + } + + /// + /// Records that the named pipe server is accepting requests. Failures before this + /// point cannot be reported over the pipe and must not wait for a reader. + /// + public void OnNamedPipeReady() + { + this.namedPipeReady = true; + } + + /// + /// Attempts to take ownership of the mount-failure path, publishing + /// as the reason if this call wins. + /// + public MountFailureOwnership TryTakeOwnership(string message) + { + int currentThreadId = Environment.CurrentManagedThreadId; + int previousOwner = Interlocked.CompareExchange(ref this.owningThreadId, currentThreadId, 0); + + if (previousOwner == currentThreadId) + { + return MountFailureOwnership.Reentrant; + } + + if (previousOwner != 0) + { + return MountFailureOwnership.NotOwner; + } + + this.failureMessage = message; + return MountFailureOwnership.Owner; + } + + /// + /// Records that a GetStatus response reached a client, and releases + /// when that response carried the + /// failure. + /// + /// + /// True when the delivered response reported MountFailed. + /// + public void OnStatusDelivered(bool carriedMountFailure) + { + // Only count a client that actually received a status. Recording this before + // the send succeeds would let a client that connected and then disconnected + // extend the post-failure wait. + this.clientReceivedStatus = true; + + if (carriedMountFailure) + { + this.failureReported.Set(); + } + } + + /// + /// Blocks until a client has read the failure, or until a short timeout elapses. + /// Returns immediately when no client could possibly read it. + /// + public void WaitForClientToReadFailure() + { + if (!this.namedPipeReady) + { + // No client can read the failure. The caller detects this case by + // watching the mount process exit code instead. + return; + } + + int timeoutMs = this.clientReceivedStatus ? this.reportTimeoutMs : this.noClientTimeoutMs; + + if (this.failureReported.WaitOne(timeoutMs)) + { + Thread.Sleep(this.drainMs); + } + else + { + this.tracer.RelatedWarning( + null, + $"{nameof(this.WaitForClientToReadFailure)}: No client read the mount failure within {timeoutMs}ms. Exiting anyway.", + Keywords.Telemetry); + } + } + + public void Dispose() + { + // InProcessMount deliberately does not call this: it holds the reporter for + // the life of the process and leaves through Environment.Exit, which reclaims + // the handle. Do not dispose while a thread is inside + // WaitForClientToReadFailure -- WaitOne on a disposed handle throws. + this.failureReported.Dispose(); + } + } +} diff --git a/GVFS/GVFS.Common/NamedPipes/NamedPipeMessages.cs b/GVFS/GVFS.Common/NamedPipes/NamedPipeMessages.cs index 62447659ee..5d1e4794a4 100644 --- a/GVFS/GVFS.Common/NamedPipes/NamedPipeMessages.cs +++ b/GVFS/GVFS.Common/NamedPipes/NamedPipeMessages.cs @@ -36,6 +36,14 @@ public class Response { public string MountStatus { get; set; } public string MountProgress { get; set; } + + /// + /// Why the mount failed. Set only when is + /// , so the client can report the real cause + /// instead of a generic failure message. + /// + public string MountError { get; set; } + public string EnlistmentRoot { get; set; } public string LocalCacheRoot { get; set; } public string RepoUrl { get; set; } diff --git a/GVFS/GVFS.Mount/InProcessMount.cs b/GVFS/GVFS.Mount/InProcessMount.cs index 629be66138..d1e5815966 100644 --- a/GVFS/GVFS.Mount/InProcessMount.cs +++ b/GVFS/GVFS.Mount/InProcessMount.cs @@ -59,6 +59,10 @@ public class InProcessMount private volatile MountState currentState; private volatile string mountProgressMessage; + // Keeps the pipe answering GetStatus after a failure so the client can read the + // reason, instead of racing this process to exit and seeing a broken pipe. + private readonly MountFailureReporter mountFailureReporter; + // When false (default), the mount process does not surface progress phase // strings over the named pipe, so the CLI falls back to its static spinner. // This gates only the display layer; the early-pipe reliability infrastructure @@ -82,6 +86,7 @@ public InProcessMount(ITracer tracer, GVFSEnlistment enlistment, CacheServerInfo this.enlistment = enlistment; this.showDebugWindow = showDebugWindow; this.unmountEvent = new ManualResetEvent(false); + this.mountFailureReporter = new MountFailureReporter(tracer); this.missingTreeTracker = new MissingTreeTracker(tracer, TrackedTreeCapacity); } @@ -258,6 +263,8 @@ private void MountWithLockAcquired(EventLevel verbosity, Keywords keywords) this.mountProgressMessage = "Authenticating and validating"; using (NamedPipeServer pipeServer = this.StartNamedPipe()) { + this.mountFailureReporter.OnNamedPipeReady(); + this.tracer.RelatedEvent( EventLevel.Informational, $"{nameof(this.Mount)}_StartedNamedPipe", @@ -640,24 +647,76 @@ private void FailMountAndExit(string error, params object[] args) private void FailMountAndExit(ReturnCode returnCode, string error, params object[] args) { + // Format before taking ownership. RelatedError would otherwise format a second + // time without protection, and a throw there would re-enter this method from an + // outer catch block. + string failureMessage = MountFailureReporter.FormatFailure(error, args); + + switch (this.mountFailureReporter.TryTakeOwnership(failureMessage)) + { + case MountFailureOwnership.Reentrant: + // Something below threw and an outer catch called back in. The failure + // was already reported, so exit rather than wait on ourselves. + this.tracer.RelatedWarning( + null, + $"{nameof(this.FailMountAndExit)}: Re-entered while reporting a mount failure: {failureMessage}", + Keywords.Telemetry); + Environment.Exit((int)returnCode); + break; + + case MountFailureOwnership.NotOwner: + // Another thread owns the failure path and will exit the process. Block + // rather than return: every caller of FailMountAndExit assumes it never + // returns and would otherwise run on with a half-initialized mount. + BlockUntilProcessExits(); + break; + } + this.currentState = MountState.MountFailed; - this.tracer.RelatedError(error, args); + this.tracer.RelatedError(failureMessage); if (this.showDebugWindow) { Console.WriteLine("\nPress Enter to Exit"); Console.ReadLine(); } - if (this.fileSystemCallbacks != null) + // Report the failure before tearing anything down. Disposal can be slow, and a + // secondary exception thrown from it would kill the process before the client + // ever reads the reason -- which is what made mount failures surface as + // BrokenPipeException instead of the real cause. + this.mountFailureReporter.WaitForClientToReadFailure(); + + try { - this.fileSystemCallbacks.Dispose(); - this.fileSystemCallbacks = null; + if (this.fileSystemCallbacks != null) + { + this.fileSystemCallbacks.Dispose(); + this.fileSystemCallbacks = null; + } + } + catch (Exception e) + { + // Traced with Telemetry because this used to be a process-fatal crash. Without + // the keyword the failure it replaced would become invisible in the field. + this.tracer.RelatedWarning( + null, + $"{nameof(this.FailMountAndExit)}: Exception while disposing file system callbacks: {e}", + Keywords.Telemetry); } Environment.Exit((int)returnCode); } + /// + /// Parks the calling thread until another thread exits the process. Used where a + /// method must not return but is not the thread that owns the exit. + /// + private static void BlockUntilProcessExits() + { + Thread.Sleep(Timeout.Infinite); + } + private T CreateOrReportAndExit(Func factory, string reportMessage) { try @@ -1418,6 +1477,8 @@ private void HandlePrefetchBlobsRequest(NamedPipeMessages.Message message, Named private void HandleGetStatusRequest(NamedPipeServer.Connection connection) { + MountState state = this.currentState; + NamedPipeMessages.GetStatus.Response response = new NamedPipeMessages.GetStatus.Response(); response.EnlistmentRoot = this.enlistment.WorkingDirectoryRoot; response.LocalCacheRoot = !string.IsNullOrWhiteSpace(this.enlistment.LocalCacheRoot) ? this.enlistment.LocalCacheRoot : this.enlistment.GitObjectsRoot; @@ -1426,7 +1487,7 @@ private void HandleGetStatusRequest(NamedPipeServer.Connection connection) response.LockStatus = this.context?.Repository?.GVFSLock != null ? this.context.Repository.GVFSLock.GetStatus() : "Unavailable"; response.DiskLayoutVersion = $"{GVFSPlatform.Instance.DiskLayoutUpgrade.Version.CurrentMajorVersion}.{GVFSPlatform.Instance.DiskLayoutUpgrade.Version.CurrentMinorVersion}"; - switch (this.currentState) + switch (state) { case MountState.Mounting: response.MountStatus = NamedPipeMessages.GetStatus.Mounting; @@ -1448,6 +1509,7 @@ private void HandleGetStatusRequest(NamedPipeServer.Connection connection) case MountState.MountFailed: response.MountStatus = NamedPipeMessages.GetStatus.MountFailed; + response.MountError = this.mountFailureReporter.FailureMessage; break; default: @@ -1455,7 +1517,12 @@ private void HandleGetStatusRequest(NamedPipeServer.Connection connection) break; } - connection.TrySendResponse(response.ToJson()); + bool sent = connection.TrySendResponse(response.ToJson()); + + if (sent) + { + this.mountFailureReporter.OnStatusDelivered(carriedMountFailure: state == MountState.MountFailed); + } } private void HandleUnmountRequest(NamedPipeServer.Connection connection) diff --git a/GVFS/GVFS.Platform.Windows/HResultExtensions.cs b/GVFS/GVFS.Platform.Windows/HResultExtensions.cs index 96df7ae84b..64b7ecf31d 100644 --- a/GVFS/GVFS.Platform.Windows/HResultExtensions.cs +++ b/GVFS/GVFS.Platform.Windows/HResultExtensions.cs @@ -6,6 +6,12 @@ public class HResultExtensions { public const int GenericProjFSError = -2147024579; // returned by ProjFS::DeleteFile() on Win server 2016 while deleting a partial file + // HRESULT_FROM_WIN32(ERROR_FILE_SYSTEM_VIRTUALIZATION_NOT_AVAILABLE (478)): + // "The file system minifilter cannot attach to the developer volume." Returned by + // StartVirtualizing when PrjFlt is not on the volume's allowed-filter list, which + // is the default on a ReFS Dev Drive. + public const int FileSystemVirtualizationNotAvailable = unchecked((int)0x800701DE); + private const int FacilityNtBit = 0x10000000; // FACILITY_NT_BIT private const int FacilityWin32 = 7; // FACILITY_WIN32 diff --git a/GVFS/GVFS.Platform.Windows/WindowsFileSystemVirtualizer.cs b/GVFS/GVFS.Platform.Windows/WindowsFileSystemVirtualizer.cs index cc4ff66863..357f77c3c5 100644 --- a/GVFS/GVFS.Platform.Windows/WindowsFileSystemVirtualizer.cs +++ b/GVFS/GVFS.Platform.Windows/WindowsFileSystemVirtualizer.cs @@ -836,6 +836,12 @@ public override bool TryStart(out string error) { this.Context.Tracer.RelatedError($"{nameof(this.virtualizationInstance.StartVirtualizing)} failed: " + result.ToString("X") + "(" + result.ToString("G") + ")"); error = "Failed to start virtualization instance (" + result.ToString() + ")"; + + if ((int)result == HResultExtensions.FileSystemVirtualizationNotAvailable) + { + error += ". " + BuildProjFsAttachRemedy(this.Context.Enlistment.WorkingDirectoryRoot); + } + return false; } @@ -847,6 +853,48 @@ protected override void OnPossibleTombstoneFolderCreated(string relativePath) this.FileSystemCallbacks.OnPossibleTombstoneFolderCreated(relativePath); } + /// + /// Builds the user-facing remedy for + /// ERROR_FILE_SYSTEM_VIRTUALIZATION_NOT_AVAILABLE, which a Dev Drive returns when + /// PrjFlt is not on its allowed-filter list. + /// + /// + /// "fsutil devdrv setFiltersAllowed" REPLACES the allowed list, and without + /// /volume it replaces the list for every developer volume on the machine. So the + /// message must tell the user to read the current list first and include it, or + /// following this advice would drop filters the machine already requires (an + /// anti-malware filter, for example). + /// + private static string BuildProjFsAttachRemedy(string enlistmentRoot) + { + string volume; + try + { + volume = Path.GetPathRoot(enlistmentRoot)?.TrimEnd(Path.DirectorySeparatorChar); + } + catch (ArgumentException) + { + volume = null; + } + + if (string.IsNullOrEmpty(volume)) + { + volume = ""; + } + + return "The ProjFS filter (PrjFlt) cannot attach to this volume. " + + $"If {volume} is a Dev Drive, PrjFlt must be on its allowed-filter list. " + + "From an elevated command prompt, list the filters that are already allowed:" + + Environment.NewLine + + $" fsutil devdrv query {volume}" + + Environment.NewLine + + "then set the list again with PrjFlt added to it:" + + Environment.NewLine + + $" fsutil devdrv setFiltersAllowed /f /volume {volume} \",PrjFlt\"" + + Environment.NewLine + + "setFiltersAllowed replaces the list, so keep the existing entries"; + } + private static void StreamCopyBlockTo(Stream input, Stream destination, long numBytes, byte[] buffer) { int read; diff --git a/GVFS/GVFS.UnitTests/Common/MountFailureReporterTests.cs b/GVFS/GVFS.UnitTests/Common/MountFailureReporterTests.cs new file mode 100644 index 0000000000..eff6091bdd --- /dev/null +++ b/GVFS/GVFS.UnitTests/Common/MountFailureReporterTests.cs @@ -0,0 +1,251 @@ +using GVFS.Common.NamedPipes; +using GVFS.Tests.Should; +using GVFS.UnitTests.Mock.Common; +using NUnit.Framework; +using System; +using System.Diagnostics; +using System.Threading; +using System.Threading.Tasks; + +namespace GVFS.UnitTests.Common +{ + /// + /// Covers the server half of the mount-failure handshake. Before this state machine + /// was extracted from InProcessMount it lived in GVFS.Mount, which GVFS.UnitTests + /// cannot reference, so none of it was covered. + /// + [TestFixture] + public class MountFailureReporterTests + { + // Deliberately much smaller than the production defaults: these only have to be + // far enough apart to tell the two timeout paths apart, and one test has to wait + // the long one out in real time. + private const int ReportTimeoutMs = 600; + private const int NoClientTimeoutMs = 200; + private const int DrainMs = 20; + + [TestCase] + public void FirstThreadTakesOwnershipAndPublishesTheMessage() + { + using (MountFailureReporter reporter = CreateReporter()) + { + reporter.FailureMessage.ShouldBeNull(); + + reporter.TryTakeOwnership("the real reason").ShouldEqual(MountFailureOwnership.Owner); + reporter.FailureMessage.ShouldEqual("the real reason"); + } + } + + [TestCase] + public void SameThreadCallingTwiceIsReentrantRatherThanBlocked() + { + using (MountFailureReporter reporter = CreateReporter()) + { + reporter.TryTakeOwnership("first").ShouldEqual(MountFailureOwnership.Owner); + + // A throw inside the reporting path can make an outer catch block call + // back in on the same thread. That must not be treated as a second thread, + // or the caller would park forever holding the mount lock and the pipe. + reporter.TryTakeOwnership("second").ShouldEqual(MountFailureOwnership.Reentrant); + + // The re-entrant call must not overwrite the reason already published. + reporter.FailureMessage.ShouldEqual("first"); + } + } + + [TestCase] + public void SecondThreadIsNotTheOwner() + { + using (MountFailureReporter reporter = CreateReporter()) + { + reporter.TryTakeOwnership("first").ShouldEqual(MountFailureOwnership.Owner); + + MountFailureOwnership fromOtherThread = MountFailureOwnership.Owner; + Task other = Task.Run(() => fromOtherThread = reporter.TryTakeOwnership("second")); + other.Wait(TimeSpan.FromSeconds(5)).ShouldBeTrue(); + + fromOtherThread.ShouldEqual(MountFailureOwnership.NotOwner); + reporter.FailureMessage.ShouldEqual("first"); + } + } + + [TestCase] + public void WaitReturnsImmediatelyWhenThePipeNeverOpened() + { + using (MountFailureReporter reporter = CreateReporter()) + { + reporter.TryTakeOwnership("failed before the pipe opened"); + + // No client can read the failure, so the process must not linger holding + // the mount lock. The caller falls back to the process exit code. + Stopwatch elapsed = Stopwatch.StartNew(); + reporter.WaitForClientToReadFailure(); + elapsed.Stop(); + + Assert.That(elapsed.ElapsedMilliseconds, Is.LessThan(NoClientTimeoutMs)); + } + } + + [TestCase] + public void WaitUsesTheShortTimeoutWhenNoClientHasReceivedAStatus() + { + using (MountFailureReporter reporter = CreateReporter()) + { + reporter.OnNamedPipeReady(); + reporter.TryTakeOwnership("nobody is listening"); + + Stopwatch elapsed = Stopwatch.StartNew(); + reporter.WaitForClientToReadFailure(); + elapsed.Stop(); + + // Should give up after the no-client timeout, well short of the full one. + Assert.That(elapsed.ElapsedMilliseconds, Is.GreaterThan(NoClientTimeoutMs / 2)); + Assert.That(elapsed.ElapsedMilliseconds, Is.LessThan(ReportTimeoutMs)); + } + } + + [TestCase] + public void WaitReturnsOnceAClientReadsTheFailure() + { + using (MountFailureReporter reporter = CreateReporter()) + { + reporter.OnNamedPipeReady(); + reporter.TryTakeOwnership("the real reason"); + reporter.OnStatusDelivered(carriedMountFailure: true); + + Stopwatch elapsed = Stopwatch.StartNew(); + reporter.WaitForClientToReadFailure(); + elapsed.Stop(); + + // Returns as soon as the failure was delivered, plus the drain. + Assert.That(elapsed.ElapsedMilliseconds, Is.LessThan(NoClientTimeoutMs)); + } + } + + [TestCase] + public void DeliveringANonFailureStatusDoesNotReleaseTheWait() + { + using (MountFailureReporter reporter = CreateReporter()) + { + reporter.OnNamedPipeReady(); + + // A client polled while the mount was still in progress. That proves + // somebody is listening, but it did not carry the failure. + reporter.OnStatusDelivered(carriedMountFailure: false); + reporter.TryTakeOwnership("the real reason"); + + Stopwatch elapsed = Stopwatch.StartNew(); + reporter.WaitForClientToReadFailure(); + elapsed.Stop(); + + // Must wait for the failure itself to be read, using the longer timeout + // because a client is known to be polling. Asserting above the SHORT + // timeout is what proves the long path was selected. + Assert.That(elapsed.ElapsedMilliseconds, Is.GreaterThan(NoClientTimeoutMs * 2)); + } + } + + [TestCase] + public void WaitIsReleasedByAClientThatReadsTheFailureLater() + { + using (MountFailureReporter reporter = CreateReporter()) + { + reporter.OnNamedPipeReady(); + reporter.OnStatusDelivered(carriedMountFailure: false); + reporter.TryTakeOwnership("the real reason"); + + Task client = Task.Run(() => + { + Thread.Sleep(50); + reporter.OnStatusDelivered(carriedMountFailure: true); + }); + + Stopwatch elapsed = Stopwatch.StartNew(); + reporter.WaitForClientToReadFailure(); + elapsed.Stop(); + + client.Wait(TimeSpan.FromSeconds(5)).ShouldBeTrue(); + + // Released by the delivery, not by the timeout. + Assert.That(elapsed.ElapsedMilliseconds, Is.LessThan(ReportTimeoutMs)); + } + } + + [TestCase] + public void ProductionDefaultsSelectTheShorterTimeoutWhenNoClientIsListening() + { + // Everything else builds the reporter through the internal test constructor, + // so this is the only cover for the public constructor and its forwarding of + // the Default* constants. Without it, swapping DefaultReportTimeoutMs and + // DefaultNoClientTimeoutMs would ship unnoticed. + using (MountFailureReporter reporter = new MountFailureReporter(new MockTracer())) + { + reporter.OnNamedPipeReady(); + reporter.TryTakeOwnership("nobody is listening"); + + Stopwatch elapsed = Stopwatch.StartNew(); + reporter.WaitForClientToReadFailure(); + elapsed.Stop(); + + // The no-client timeout must be the one used, and it must be meaningfully + // shorter than the timeout used once a client is known to be polling. + Assert.That(elapsed.ElapsedMilliseconds, Is.GreaterThan(MountFailureReporter.DefaultNoClientTimeoutMs / 2)); + Assert.That(elapsed.ElapsedMilliseconds, Is.LessThan(MountFailureReporter.DefaultReportTimeoutMs)); + } + } + + [TestCase] + public void ProductionDefaultsAreOrderedSensibly() + { + // A failed mount holds the mount lock and the named pipe until it exits, so + // these bound how long a user's next "gvfs mount" is delayed. + Assert.That( + MountFailureReporter.DefaultNoClientTimeoutMs, + Is.LessThan(MountFailureReporter.DefaultReportTimeoutMs), + "Waiting for a client that has never polled must not take longer than waiting for one that has."); + + // The drain has to outlast the client's 100ms GetStatus poll interval, or a + // concurrent "gvfs status" can consume the report signal and the mounting + // client never gets its answer. + Assert.That( + MountFailureReporter.DefaultDrainMs, + Is.GreaterThan(100), + "The drain must exceed the client's GetStatus poll interval."); + } + + [TestCase] + public void FormatFailureAppliesArguments() + { + MountFailureReporter.FormatFailure("Error: {0}", new object[] { "boom" }) + .ShouldEqual("Error: boom"); + } + + [TestCase] + public void FormatFailureLeavesTheMessageAloneWhenThereAreNoArguments() + { + // A pre-built message can legitimately contain braces, so it must not be run + // through string.Format when there is nothing to substitute. + MountFailureReporter.FormatFailure("a message with {braces} in it", null) + .ShouldEqual("a message with {braces} in it"); + + MountFailureReporter.FormatFailure("a message with {braces} in it", new object[0]) + .ShouldEqual("a message with {braces} in it"); + } + + [TestCase] + public void FormatFailureFallsBackWhenTheFormatStringIsMalformed() + { + // Failure text is built from exception messages and server responses, which + // can contain unbalanced braces. Formatting must never throw and mask the + // failure being reported. + string result = MountFailureReporter.FormatFailure("unbalanced {0} and {", new object[] { "value" }); + + result.ShouldEqual("unbalanced {0} and {"); + } + + private static MountFailureReporter CreateReporter() + { + return new MountFailureReporter(new MockTracer(), ReportTimeoutMs, NoClientTimeoutMs, DrainMs); + } + } +} diff --git a/GVFS/GVFS.UnitTests/Common/WaitUntilMountedFailureReportingTests.cs b/GVFS/GVFS.UnitTests/Common/WaitUntilMountedFailureReportingTests.cs new file mode 100644 index 0000000000..cbe6288222 --- /dev/null +++ b/GVFS/GVFS.UnitTests/Common/WaitUntilMountedFailureReportingTests.cs @@ -0,0 +1,102 @@ +using GVFS.Common; +using GVFS.Common.NamedPipes; +using GVFS.Tests.Should; +using GVFS.UnitTests.Mock.Common; +using NUnit.Framework; +using System; +using System.IO.Pipes; +using System.Threading.Tasks; + +namespace GVFS.UnitTests.Common +{ + [TestFixture] + public class WaitUntilMountedFailureReportingTests + { + private const string EnlistmentRoot = "C:\\fake\\root"; + + [TestCase] + public void ReportsTheMountErrorSentByTheMountProcess() + { + const string MountError = + "Error: Failed to start virtualization instance (-2147024418). " + + "The ProjFS filter (PrjFlt) cannot attach to this volume."; + + string errorMessage = RunAgainstMountFailedServer(MountError); + + errorMessage.ShouldEqual(MountError); + } + + [TestCase] + public void FallsBackToGenericMessageWhenNoMountErrorIsSent() + { + string errorMessage = RunAgainstMountFailedServer(mountError: null); + + errorMessage.ShouldEqual("Failed to mount at " + EnlistmentRoot); + } + + /// + /// Stands in for GVFS.Mount: answers a single GetStatus request with MountFailed, + /// then returns the error message WaitUntilMounted produced. + /// + /// + /// Uses a raw rather than + /// , because the latter goes through + /// GVFSPlatform.CreatePipeByName, which the unit-test mock platform does not + /// support. + /// + private static string RunAgainstMountFailedServer(string mountError) + { + string pipeName = "GVFS_test_mount_failed_" + Guid.NewGuid().ToString("N"); + + NamedPipeMessages.GetStatus.Response response = new NamedPipeMessages.GetStatus.Response + { + MountStatus = NamedPipeMessages.GetStatus.MountFailed, + MountError = mountError, + EnlistmentRoot = EnlistmentRoot, + }; + + string responseJson = response.ToJson(); + + using (NamedPipeServerStream serverStream = new NamedPipeServerStream( + pipeName, + PipeDirection.InOut, + maxNumberOfServerInstances: 1)) + { + Task serverTask = Task.Run(() => + { + serverStream.WaitForConnection(); + + NamedPipeStreamReader reader = new NamedPipeStreamReader(serverStream); + NamedPipeStreamWriter writer = new NamedPipeStreamWriter(serverStream); + + // WaitUntilMounted sends GetStatus and stops on the first + // MountFailed response, so one exchange is enough. + reader.ReadMessage(); + writer.WriteMessage(responseJson); + }); + + try + { + string errorMessage; + bool result = GVFSEnlistment.WaitUntilMounted( + new MockTracer(), + pipeName, + EnlistmentRoot, + unattended: false, + out errorMessage); + + result.ShouldBeFalse(); + return errorMessage; + } + finally + { + // Surfaces a hung server task instead of silently disposing the stream + // out from under it, which would fault an unobserved task and hide the + // real cause of a failure. + serverTask.Wait(TimeSpan.FromSeconds(5)).ShouldBeTrue( + "The stand-in mount server should have answered and completed."); + } + } + } + } +} diff --git a/GVFS/GVFS.UnitTests/Virtualization/Background/BackgroundFileSystemTaskRunnerDisposeTests.cs b/GVFS/GVFS.UnitTests/Virtualization/Background/BackgroundFileSystemTaskRunnerDisposeTests.cs new file mode 100644 index 0000000000..8a390510fc --- /dev/null +++ b/GVFS/GVFS.UnitTests/Virtualization/Background/BackgroundFileSystemTaskRunnerDisposeTests.cs @@ -0,0 +1,45 @@ +using GVFS.Virtualization.Background; +using NUnit.Framework; +using System.Threading; +using System.Threading.Tasks; + +namespace GVFS.UnitTests.Virtualization.Background +{ + [TestFixture] + public class BackgroundFileSystemTaskRunnerDisposeTests + { + [TestCase] + public void DisposeDoesNotThrowWhenBackgroundThreadIsStillRunning() + { + using (ManualResetEventSlim releaseBackgroundThread = new ManualResetEventSlim(false)) + { + Task backgroundThread = Task.Factory.StartNew( + () => releaseBackgroundThread.Wait(), + TaskCreationOptions.LongRunning); + + try + { + TestableBackgroundFileSystemTaskRunner runner = new TestableBackgroundFileSystemTaskRunner(); + runner.SetBackgroundThreadForTests(backgroundThread); + + // FileSystemCallbacks.Dispose() disposes this runner on the failed-mount + // path, without calling Shutdown first, so the background thread is still + // running. Calling Task.Dispose on a task that has not completed throws + // InvalidOperationException, which stopped GVFS.Mount from reporting why + // the mount failed. This guards against reintroducing that call. + Assert.DoesNotThrow(() => runner.Dispose()); + } + finally + { + releaseBackgroundThread.Set(); + backgroundThread.Wait(); + backgroundThread.Dispose(); + } + } + } + + private class TestableBackgroundFileSystemTaskRunner : BackgroundFileSystemTaskRunner + { + } + } +} diff --git a/GVFS/GVFS.UnitTests/Virtualization/Projection/GitIndexProjectionDisposeTests.cs b/GVFS/GVFS.UnitTests/Virtualization/Projection/GitIndexProjectionDisposeTests.cs new file mode 100644 index 0000000000..68ae38b29f --- /dev/null +++ b/GVFS/GVFS.UnitTests/Virtualization/Projection/GitIndexProjectionDisposeTests.cs @@ -0,0 +1,46 @@ +using GVFS.Virtualization.Projection; +using NUnit.Framework; +using System.Threading; +using System.Threading.Tasks; + +namespace GVFS.UnitTests.Virtualization.Projection +{ + [TestFixture] + public class GitIndexProjectionDisposeTests + { + [TestCase] + public void DisposeDoesNotThrowWhenIndexParsingThreadIsStillRunning() + { + using (ManualResetEventSlim releaseParsingThread = new ManualResetEventSlim(false)) + { + Task parsingThread = Task.Factory.StartNew( + () => releaseParsingThread.Wait(), + TaskCreationOptions.LongRunning); + + try + { + TestableGitIndexProjection projection = new TestableGitIndexProjection(); + projection.SetIndexParsingThreadForTests(parsingThread); + + // A failed mount disposes the projection without calling Shutdown, so + // the parsing thread is still running here. Calling Task.Dispose on a + // task that has not completed throws InvalidOperationException, and + // that secondary exception used to kill GVFS.Mount before it could + // report why the mount failed -- leaving the client with a broken pipe. + // This guards against reintroducing that call. + Assert.DoesNotThrow(() => projection.Dispose()); + } + finally + { + releaseParsingThread.Set(); + parsingThread.Wait(); + parsingThread.Dispose(); + } + } + } + + private class TestableGitIndexProjection : GitIndexProjection + { + } + } +} diff --git a/GVFS/GVFS.Virtualization/Background/BackgroundFileSystemTaskRunner.cs b/GVFS/GVFS.Virtualization/Background/BackgroundFileSystemTaskRunner.cs index 88ea897098..21316fbf6d 100644 --- a/GVFS/GVFS.Virtualization/Background/BackgroundFileSystemTaskRunner.cs +++ b/GVFS/GVFS.Virtualization/Background/BackgroundFileSystemTaskRunner.cs @@ -122,13 +122,27 @@ public void Dispose() GC.SuppressFinalize(this); } + /// + /// Test seam. Puts the runner into the "background thread is still running" state + /// that a failed mount produces, without needing a real repo. + /// + internal void SetBackgroundThreadForTests(Task backgroundTask) + { + this.backgroundThread = backgroundTask; + } + protected void Dispose(bool disposing) { if (disposing) { if (this.backgroundThread != null) { - this.backgroundThread.Dispose(); + // Deliberately not calling Task.Dispose. A Task holds no unmanaged + // resources, and Task.Dispose throws InvalidOperationException unless + // the task has reached a completion state. A failed mount disposes the + // callbacks without calling Shutdown first, so this thread is still + // running and that throw would prevent the mount process from + // reporting why the mount failed. this.backgroundThread = null; } if (this.backgroundTasks != null) diff --git a/GVFS/GVFS.Virtualization/Projection/GitIndexProjection.cs b/GVFS/GVFS.Virtualization/Projection/GitIndexProjection.cs index 3b8301b125..131449e640 100644 --- a/GVFS/GVFS.Virtualization/Projection/GitIndexProjection.cs +++ b/GVFS/GVFS.Virtualization/Projection/GitIndexProjection.cs @@ -706,6 +706,15 @@ public void Dispose() GC.SuppressFinalize(this); } + /// + /// Test seam. Puts the projection into the "index parsing thread is still + /// running" state that a failed mount produces, without needing a real repo. + /// + internal void SetIndexParsingThreadForTests(Task indexParsingTask) + { + this.indexParsingThread = indexParsingTask; + } + protected virtual void Dispose(bool disposing) { if (disposing) @@ -730,7 +739,13 @@ protected virtual void Dispose(bool disposing) if (this.indexParsingThread != null) { - this.indexParsingThread.Dispose(); + // Deliberately not calling Task.Dispose. A Task holds no unmanaged + // resources, Task.Dispose is legacy IAsyncResult wait-handle cleanup, + // and it throws InvalidOperationException unless the task has reached + // a completion state. A failed mount disposes the projection without + // calling Shutdown first, so the parsing thread is still running here + // and that throw would kill the mount process before it can report + // why the mount failed. this.indexParsingThread = null; } }