diff --git a/GVFS/GVFS.Common/GVFSConstants.cs b/GVFS/GVFS.Common/GVFSConstants.cs index 5cf22eabe..8ae80dd5a 100644 --- a/GVFS/GVFS.Common/GVFSConstants.cs +++ b/GVFS/GVFS.Common/GVFSConstants.cs @@ -83,6 +83,13 @@ public static class GitConfig public const string MaxHttpConnectionsConfig = GVFSPrefix + "max-http-connections"; + /// + /// Overrides how long credential operations started by HTTP requests can wait for + /// the credential manager, in seconds. 0 or negative selects an unbounded wait. + /// Startup authentication continues to use its fixed startup bound. + /// + public const string CredentialTimeoutSeconds = GVFSPrefix + "credential-timeout-seconds"; + public const string PrefetchUseIdx = GVFSPrefix + "prefetch-use-idx"; public const bool PrefetchUseIdxDefault = false; @@ -95,6 +102,7 @@ public static class GitConfig public const string PrefetchOffload = GVFSPrefix + "prefetch-offload"; public const bool PrefetchOffloadDefault = false; + } public static class LocalGVFSConfig diff --git a/GVFS/GVFS.Common/Git/GVFSGitObjects.cs b/GVFS/GVFS.Common/Git/GVFSGitObjects.cs index 38065f28f..d90fc65c4 100644 --- a/GVFS/GVFS.Common/Git/GVFSGitObjects.cs +++ b/GVFS/GVFS.Common/Git/GVFSGitObjects.cs @@ -70,11 +70,13 @@ internal class DownloadAttemptResult public DownloadAttemptResult( DownloadAndSaveObjectResult result, HttpStatusCode? httpStatusCode, - bool shouldRecordFailure = true) + bool shouldRecordFailure = true, + bool credentialOperationTimedOut = false) { this.Result = result; this.HttpStatusCode = httpStatusCode; this.ShouldRecordFailure = shouldRecordFailure; + this.CredentialOperationTimedOut = credentialOperationTimedOut; } public DownloadAndSaveObjectResult Result { get; } @@ -84,6 +86,8 @@ public DownloadAttemptResult( public HttpStatusCode? HttpStatusCode { get; } public bool ShouldRecordFailure { get; } + + public bool CredentialOperationTimedOut { get; } } protected GVFSContext Context { get; private set; } @@ -171,6 +175,7 @@ public virtual bool TryCopyBlobContentStream( capturedCategory = category; metadata.Add(nameof(BlobHydrationFailureCategory), category.ToString()); + metadata.Add("CredentialOperationTimedOut", lastDownloadResult?.CredentialOperationTimedOut ?? false); // Surface the HTTP status of the last download attempt so telemetry can tell a // genuine auth failure (401/400/302) apart from a transient one (408/5xx/503), @@ -225,7 +230,7 @@ public virtual bool TryCopyBlobContentStream( return new RetryWrapper.CallbackResult( error: null, - shouldRetry: true, + shouldRetry: !lastDownloadResult.CredentialOperationTimedOut, result: false, shouldRecordFailure: lastDownloadResult?.ShouldRecordFailure ?? true); } @@ -368,6 +373,7 @@ private DownloadAttemptResult DoDownloadAndSaveObject( // known. A default (zero) status means the result carried no HTTP response, so it is // treated as "no status". HttpStatusCode? httpStatusCode = null; + bool credentialOperationTimedOut = output.Result?.CredentialOperationTimedOut ?? false; if (output.Result != null && output.Result.HttpStatusCodeResult != 0) { httpStatusCode = output.Result.HttpStatusCodeResult; @@ -380,7 +386,8 @@ private DownloadAttemptResult DoDownloadAndSaveObject( return new DownloadAttemptResult( DownloadAndSaveObjectResult.Success, httpStatusCode, - output.ShouldRecordFailure); + output.ShouldRecordFailure, + credentialOperationTimedOut); } if (output.Result.HttpStatusCodeResult == HttpStatusCode.NotFound) @@ -389,14 +396,16 @@ private DownloadAttemptResult DoDownloadAndSaveObject( return new DownloadAttemptResult( DownloadAndSaveObjectResult.ObjectNotOnServer, httpStatusCode, - output.ShouldRecordFailure); + output.ShouldRecordFailure, + credentialOperationTimedOut); } } return new DownloadAttemptResult( DownloadAndSaveObjectResult.Error, httpStatusCode, - output.ShouldRecordFailure); + output.ShouldRecordFailure, + credentialOperationTimedOut); } } } \ No newline at end of file diff --git a/GVFS/GVFS.Common/Git/GitAuthentication.cs b/GVFS/GVFS.Common/Git/GitAuthentication.cs index 5f9db0c72..145e1a529 100644 --- a/GVFS/GVFS.Common/Git/GitAuthentication.cs +++ b/GVFS/GVFS.Common/Git/GitAuthentication.cs @@ -2,6 +2,7 @@ using GVFS.Common.Tracing; using System; using System.Collections.Generic; +using System.Diagnostics; using System.Net; using System.Net.Http; using System.Security.Cryptography.X509Certificates; @@ -20,10 +21,17 @@ private enum AuthenticationState } private const double MaxBackoffSeconds = 30; + private const int CredentialTimeoutBackoffAttempt = 5; public const int DefaultCredentialTimeoutMs = 30_000; public const int BackgroundCredentialTimeoutMs = 120_000; - private readonly Lock gitAuthLock = new Lock(); + /// + /// Minimum time to wait for an in-flight credential fetch before giving up on + /// serialization. The effective wait is never shorter than the fetch timeout. + /// + private const int DefaultCredentialGateWaitMs = 60_000; + + private readonly SemaphoreSlim gitAuthLock = new SemaphoreSlim(1, 1); private readonly SemaphoreSlim credentialGate = new SemaphoreSlim(1, 1); private readonly ICredentialStore credentialStore; private readonly string repoUrl; @@ -38,6 +46,7 @@ private enum AuthenticationState private int numberOfAttempts = 0; private DateTime lastAuthAttempt = DateTime.MinValue; + private bool backoffIsCredentialTimeout; private string cachedCredentialString; private bool isCachedCredentialStringApproved = false; @@ -114,17 +123,38 @@ internal void MarkInitializationStarted() /// internal IGVFSConfigRequestor ConfigRequestorOverride { get; set; } + internal int CredentialGateWaitTimeoutMs { get; set; } = DefaultCredentialGateWaitMs; + private GitSsl GitSsl { get; } - public void ApproveCredentials(ITracer tracer, string credentialString) + /// + /// Test-only hook to force the anonymous state. Production code determines this + /// by probing the server in . + /// + internal void SetIsAnonymousForTesting(bool isAnonymous) { - lock (this.gitAuthLock) + if (isAnonymous) + { + this.MarkAnonymousAccessSucceeded(); + } + else + { + this.MarkAuthenticationRequired(); + } + + this.MarkInitialized(); + } + + public void ApproveCredentials(ITracer tracer, string credentialString, int credentialTimeoutMs = DefaultCredentialTimeoutMs, CancellationToken cancellationToken = default) + { + using (new SemaphoreScope(this.gitAuthLock, cancellationToken)) { // Don't reset the backoff if this is for a different credential than we have cached if (credentialString == this.cachedCredentialString) { this.numberOfAttempts = 0; this.lastAuthAttempt = DateTime.MinValue; + this.backoffIsCredentialTimeout = false; // Tell Git to store the valid credential if we haven't already // done so for this cached credential. @@ -134,10 +164,14 @@ public void ApproveCredentials(ITracer tracer, string credentialString) string password; if (TryParseCredentialString(this.cachedCredentialString, out username, out password)) { - if (!this.credentialStore.TryStoreCredential(tracer, this.repoUrl, username, password, out string error)) + if (!this.TryStoreCredential(tracer, username, password, out string error, out bool timedOut, credentialTimeoutMs, cancellationToken)) { // Storing credentials is best effort attempt - log failure, but do not fail tracer.RelatedWarning("Failed to store credential string: {0}", error); + if (timedOut) + { + this.TraceCredentialOperationTimeout(tracer, "approve", credentialTimeoutMs); + } } this.isCachedCredentialStringApproved = true; @@ -155,10 +189,11 @@ public void ApproveCredentials(ITracer tracer, string credentialString) } } - public void RejectCredentials(ITracer tracer, string credentialString) + public bool RejectCredentials(ITracer tracer, string credentialString, int credentialTimeoutMs = DefaultCredentialTimeoutMs, CancellationToken cancellationToken = default) { - lock (this.gitAuthLock) + using (new SemaphoreScope(this.gitAuthLock, cancellationToken)) { + Stopwatch credentialStopwatch = Stopwatch.StartNew(); string cachedCredentialAtStartOfReject = this.cachedCredentialString; // Don't stomp a different credential if (credentialString == cachedCredentialAtStartOfReject && cachedCredentialAtStartOfReject != null) @@ -166,18 +201,25 @@ public void RejectCredentials(ITracer tracer, string credentialString) // We can't assume that the credential store's cached credential is the same as the one we have. // Reload the credential from the store to ensure we're rejecting the correct one. int attemptsBeforeCheckingExistingCredential = this.numberOfAttempts; - if (this.TryCallGitCredential(tracer, out string getCredentialError)) + int remainingTimeoutMs = GetRemainingTimeoutMs(credentialTimeoutMs, credentialStopwatch); + if (this.TryCallGitCredential(tracer, out string getCredentialError, out bool reloadTimedOut, remainingTimeoutMs, cancellationToken)) { if (this.cachedCredentialString != cachedCredentialAtStartOfReject) { // If the store already had a different credential, we don't want to reject it without trying it. this.isCachedCredentialStringApproved = false; - return; + return false; } } else { tracer.RelatedWarning(getCredentialError); + if (reloadTimedOut) + { + this.ClearCachedCredential(); + this.TraceCredentialOperationTimeout(tracer, "reload", credentialTimeoutMs); + return true; + } } // If we can we should pass the actual username/password values we used (and found to be invalid) @@ -187,10 +229,26 @@ public void RejectCredentials(ITracer tracer, string credentialString) string password; if (TryParseCredentialString(this.cachedCredentialString, out username, out password)) { - if (!this.credentialStore.TryDeleteCredential(tracer, this.repoUrl, username, password, out string error)) + remainingTimeoutMs = GetRemainingTimeoutMs(credentialTimeoutMs, credentialStopwatch); + if (remainingTimeoutMs == 0) + { + this.UpdateBackoff(requireDelay: true, credentialOperationTimedOut: true); + this.ClearCachedCredential(); + this.TraceCredentialOperationTimeout(tracer, "delete", credentialTimeoutMs); + return true; + } + + if (!this.TryDeleteCredential(tracer, username, password, out string error, out bool deleteTimedOut, remainingTimeoutMs, CancellationToken.None)) { // Deleting credentials is best effort attempt - log failure, but do not fail tracer.RelatedWarning("Failed to delete credential string: {0}", error); + if (deleteTimedOut) + { + this.UpdateBackoff(requireDelay: true, credentialOperationTimedOut: true); + this.ClearCachedCredential(); + this.TraceCredentialOperationTimeout(tracer, "delete", credentialTimeoutMs); + return true; + } } } else @@ -202,11 +260,26 @@ public void RejectCredentials(ITracer tracer, string credentialString) ["RepoUrl"] = this.repoUrl, }); tracer.RelatedWarning(metadata, "Failed to parse credential string for rejection. Rejecting any credential for this repo URL."); - this.credentialStore.TryDeleteCredential(tracer, this.repoUrl, username: null, password: null, error: out string error); + remainingTimeoutMs = GetRemainingTimeoutMs(credentialTimeoutMs, credentialStopwatch); + if (remainingTimeoutMs == 0) + { + this.UpdateBackoff(requireDelay: true, credentialOperationTimedOut: true); + this.ClearCachedCredential(); + this.TraceCredentialOperationTimeout(tracer, "delete", credentialTimeoutMs); + return true; + } + + this.TryDeleteCredential(tracer, username: null, password: null, error: out string error, timedOut: out bool deleteTimedOut, timeoutMs: remainingTimeoutMs, cancellationToken: CancellationToken.None); + if (deleteTimedOut) + { + this.UpdateBackoff(requireDelay: true, credentialOperationTimedOut: true); + this.ClearCachedCredential(); + this.TraceCredentialOperationTimeout(tracer, "delete", credentialTimeoutMs); + return true; + } } - this.cachedCredentialString = null; - this.isCachedCredentialStringApproved = false; + this.ClearCachedCredential(); // Backoff may have already been incremented by a failure in TryCallGitCredential if (attemptsBeforeCheckingExistingCredential == this.numberOfAttempts) @@ -214,6 +287,8 @@ public void RejectCredentials(ITracer tracer, string credentialString) this.UpdateBackoff(); } } + + return false; } } @@ -230,8 +305,20 @@ public void RejectCredentials(ITracer tracer, string credentialString) /// True when the request can proceed: with the credential in /// , or anonymously when it is null. /// - public bool TryGetCredentials(ITracer tracer, out string credentialString, out string errorMessage) + public bool TryGetCredentials(ITracer tracer, out string credentialString, out string errorMessage, int credentialTimeoutMs = DefaultCredentialTimeoutMs, CancellationToken cancellationToken = default) + { + return this.TryGetCredentials(tracer, out credentialString, out errorMessage, out _, credentialTimeoutMs, cancellationToken); + } + + /// + /// Fetches credentials, reporting via whether the failure was + /// the credential manager exceeding its bound rather than a genuine auth failure. Callers + /// use this to avoid immediately retrying, which would re-prompt the user. + /// + public bool TryGetCredentials(ITracer tracer, out string credentialString, out string errorMessage, out bool timedOut, int credentialTimeoutMs = DefaultCredentialTimeoutMs, CancellationToken cancellationToken = default) { + timedOut = false; + if (!this.isInitialized) { // Initialization may still be running in the background (mount can @@ -239,7 +326,7 @@ public bool TryGetCredentials(ITracer tracer, out string credentialString, out s // finished when a cache server is configured). Wait for it to // complete rather than throwing an unhandled exception into the // virtualization callback, which would crash the mount process. - if (!this.initializationComplete.Wait(this.InitializationWaitTimeoutMs)) + if (!this.initializationComplete.Wait(this.InitializationWaitTimeoutMs, cancellationToken)) { credentialString = null; errorMessage = "Timed out waiting for authentication to initialize"; @@ -257,17 +344,18 @@ public bool TryGetCredentials(ITracer tracer, out string credentialString, out s credentialString = this.cachedCredentialString; if (credentialString == null) { - lock (this.gitAuthLock) + using (new SemaphoreScope(this.gitAuthLock, cancellationToken)) { if (this.cachedCredentialString == null) { if (this.IsBackingOff) { + timedOut = this.backoffIsCredentialTimeout; errorMessage = "Auth failed. No retries will be made until: " + this.GetNextAuthAttemptTime(); return false; } - if (!this.TryCallGitCredential(tracer, out errorMessage)) + if (!this.TryCallGitCredential(tracer, out errorMessage, out timedOut, credentialTimeoutMs, cancellationToken)) { return false; } @@ -402,7 +490,7 @@ private bool TryInitializeAndQueryGVFSConfigCore( // Server requires authentication — fetch credentials this.MarkAuthenticationRequired(); - if (!this.TryCallGitCredential(tracer, out errorMessage, credentialTimeoutMs)) + if (!this.TryCallGitCredential(tracer, out errorMessage, out _, credentialTimeoutMs)) { isAuthFailure = true; // Mark initialized even on failure so TryGetCredentials can @@ -437,7 +525,7 @@ private bool TryInitializeAndQueryGVFSConfigCore( /// Test-only initialization that skips the network probe and goes /// straight to credential fetch. Not for production use. /// - internal bool TryInitializeAndRequireAuth(ITracer tracer, out string errorMessage) + internal bool TryInitializeAndRequireAuth(ITracer tracer, out string errorMessage, int credentialTimeoutMs = Timeout.Infinite) { if (this.isInitialized) { @@ -449,7 +537,7 @@ internal bool TryInitializeAndRequireAuth(ITracer tracer, out string errorMessag try { - if (this.TryCallGitCredential(tracer, out errorMessage)) + if (this.TryCallGitCredential(tracer, out errorMessage, out _, credentialTimeoutMs)) { this.MarkInitialized(); return true; @@ -569,10 +657,47 @@ private DateTime GetNextAuthAttemptTime() return this.lastAuthAttempt + TimeSpan.FromSeconds(backoffSeconds); } - private void UpdateBackoff() + private void UpdateBackoff(bool requireDelay = false, bool credentialOperationTimedOut = false) { this.lastAuthAttempt = DateTime.Now; this.numberOfAttempts++; + this.backoffIsCredentialTimeout = credentialOperationTimedOut; + if (requireDelay && credentialOperationTimedOut) + { + this.numberOfAttempts = Math.Max(this.numberOfAttempts, CredentialTimeoutBackoffAttempt); + } + else if (requireDelay && this.numberOfAttempts == 1) + { + this.numberOfAttempts++; + } + } + + private static int GetRemainingTimeoutMs(int timeoutMs, Stopwatch stopwatch) + { + if (timeoutMs < 0) + { + return Timeout.Infinite; + } + + return (int)Math.Max(0, timeoutMs - stopwatch.ElapsedMilliseconds); + } + + private void ClearCachedCredential() + { + this.cachedCredentialString = null; + this.isCachedCredentialStringApproved = false; + } + + private void TraceCredentialOperationTimeout(ITracer tracer, string operation, int timeoutMs) + { + EventMetadata metadata = new EventMetadata(); + metadata.Add("Operation", operation); + metadata.Add("timeoutMs", timeoutMs); + tracer.RelatedEvent( + EventLevel.Warning, + "CredentialOperationTimedOut", + metadata, + Keywords.Network | Keywords.Telemetry); } private void MarkInitialized() @@ -583,28 +708,40 @@ private void MarkInitialized() this.initializationComplete.Set(); } - private bool TryCallGitCredential(ITracer tracer, out string errorMessage, int timeoutMs = -1) + private bool TryCallGitCredential(ITracer tracer, out string errorMessage, out bool timedOut, int timeoutMs = -1, CancellationToken cancellationToken = default) { - // Serialize credential fetches so only one git-credential-fill - // process runs at a time. Without this, a background auth task - // and a foreground object download could both spawn GCM prompts. - // Wait up to 60s for an in-flight fetch; if the gate is still - // held (e.g., background GCM prompt), fall through and let this - // caller spawn its own credential fetch. - bool acquired = this.credentialGate.Wait(60_000); + cancellationToken.ThrowIfCancellationRequested(); + timedOut = false; + + int gateTimeoutMs = timeoutMs < 0 ? Timeout.Infinite : Math.Max(this.CredentialGateWaitTimeoutMs, timeoutMs); + if (!this.credentialGate.Wait(gateTimeoutMs, cancellationToken)) + { + timedOut = true; + errorMessage = "Timed out waiting for another credential operation"; + this.UpdateBackoff(requireDelay: true, credentialOperationTimedOut: true); + return false; + } + try { - string gitUsername; - string gitPassword; - if (!this.credentialStore.TryGetCredential(tracer, this.repoUrl, out gitUsername, out gitPassword, out errorMessage, timeoutMs)) + bool succeeded = this.credentialStore.TryGetCredential( + tracer, + this.repoUrl, + out string username, + out string password, + out errorMessage, + out timedOut, + timeoutMs, + CancellationToken.None); + if (!succeeded) { - this.UpdateBackoff(); + this.UpdateBackoff(requireDelay: timedOut, credentialOperationTimedOut: timedOut); return false; } - if (!string.IsNullOrEmpty(gitPassword)) + if (!string.IsNullOrEmpty(password)) { - this.cachedCredentialString = Convert.ToBase64String(Encoding.UTF8.GetBytes(gitUsername + ":" + gitPassword)); + this.cachedCredentialString = Convert.ToBase64String(Encoding.UTF8.GetBytes(username + ":" + password)); this.isCachedCredentialStringApproved = false; } else @@ -617,10 +754,95 @@ private bool TryCallGitCredential(ITracer tracer, out string errorMessage, int t } finally { - if (acquired) - { - this.credentialGate.Release(); - } + this.credentialGate.Release(); + } + } + + private bool TryStoreCredential( + ITracer tracer, + string username, + string password, + out string error, + out bool timedOut, + int timeoutMs, + CancellationToken cancellationToken) + { + cancellationToken.ThrowIfCancellationRequested(); + int gateTimeoutMs = timeoutMs < 0 ? Timeout.Infinite : Math.Max(this.CredentialGateWaitTimeoutMs, timeoutMs); + if (!this.credentialGate.Wait(gateTimeoutMs, cancellationToken)) + { + timedOut = true; + error = "Timed out waiting for another credential operation"; + return false; + } + + try + { + return this.credentialStore.TryStoreCredential( + tracer, + this.repoUrl, + username, + password, + out error, + out timedOut, + timeoutMs, + CancellationToken.None); + } + finally + { + this.credentialGate.Release(); + } + } + + private bool TryDeleteCredential( + ITracer tracer, + string username, + string password, + out string error, + out bool timedOut, + int timeoutMs, + CancellationToken cancellationToken) + { + cancellationToken.ThrowIfCancellationRequested(); + int gateTimeoutMs = timeoutMs < 0 ? Timeout.Infinite : Math.Max(this.CredentialGateWaitTimeoutMs, timeoutMs); + if (!this.credentialGate.Wait(gateTimeoutMs, cancellationToken)) + { + timedOut = true; + error = "Timed out waiting for another credential operation"; + return false; + } + + try + { + return this.credentialStore.TryDeleteCredential( + tracer, + this.repoUrl, + username, + password, + out error, + out timedOut, + timeoutMs, + CancellationToken.None); + } + finally + { + this.credentialGate.Release(); + } + } + + private readonly struct SemaphoreScope : IDisposable + { + private readonly SemaphoreSlim semaphore; + + public SemaphoreScope(SemaphoreSlim semaphore, CancellationToken cancellationToken) + { + this.semaphore = semaphore; + this.semaphore.Wait(cancellationToken); + } + + public void Dispose() + { + this.semaphore.Release(); } } } diff --git a/GVFS/GVFS.Common/Git/GitProcess.cs b/GVFS/GVFS.Common/Git/GitProcess.cs index d97e3af85..64e623511 100644 --- a/GVFS/GVFS.Common/Git/GitProcess.cs +++ b/GVFS/GVFS.Common/Git/GitProcess.cs @@ -39,11 +39,7 @@ public class GitProcess : ICredentialStore /// /// Upper bound on how long the NUL-streaming path waits for a git process to exit after its - /// stdout has reached EOF, when the caller did not set a finite timeout. Once stdout closes the - /// process is normally about to exit, so this only matters in the pathological case where git - /// wedges or a timeout tree-kill only partially succeeds (a surviving grandchild still holding - /// the pipe). Bounding the wait guarantees the streaming path can never pin the calling thread - /// indefinitely - the maintenance/prefetch hang this streaming change is meant to avoid. + /// stdout has reached EOF, when the caller did not set a finite timeout. /// private const int DefaultPostReadGraceMs = 60 * 1000; @@ -51,6 +47,13 @@ public class GitProcess : ICredentialStore private const int MaxCredentialOutputKeys = 32; private const int MaxCredentialOutputKeyLength = 32; + /// + /// How long to wait for a killed process tree to actually exit before we give up + /// and read whatever the async stdout/stderr readers have captured so far. + /// + private const int ProcessKillTimeoutMs = 5_000; + private const int OutputDrainPollIntervalMs = 10; + private static readonly Encoding UTF8NoBOM = new UTF8Encoding(false); // Key names defined by the git credential protocol. They are names, not values, so they are @@ -280,8 +283,9 @@ public bool TryKillRunningProcess(out string processName, out int exitCode, out } } - public virtual bool TryDeleteCredential(ITracer tracer, string repoUrl, string username, string password, out string errorMessage) + public virtual bool TryDeleteCredential(ITracer tracer, string repoUrl, string username, string password, out string errorMessage, out bool timedOut, int timeoutMs = -1, CancellationToken cancellationToken = default) { + timedOut = false; StringBuilder sb = new StringBuilder(); sb.AppendFormat("url={0}\n", repoUrl); @@ -301,10 +305,13 @@ public virtual bool TryDeleteCredential(ITracer tracer, string repoUrl, string u Result result = this.InvokeGitAgainstDotGitFolderOrOutsideEnlistment( GenerateCredentialVerbCommand("reject"), stdin => stdin.Write(stdinConfig), - usePreCommandHook: false); + usePreCommandHook: false, + timeoutMs: timeoutMs, + cancellationToken: cancellationToken); if (result.ExitCodeIsFailure) { + timedOut = IsTimeoutResult(result); tracer.RelatedWarning("Git could not reject credentials: {0}", result.Errors); errorMessage = result.Errors; @@ -315,8 +322,9 @@ public virtual bool TryDeleteCredential(ITracer tracer, string repoUrl, string u return true; } - public virtual bool TryStoreCredential(ITracer tracer, string repoUrl, string username, string password, out string errorMessage) + public virtual bool TryStoreCredential(ITracer tracer, string repoUrl, string username, string password, out string errorMessage, out bool timedOut, int timeoutMs = -1, CancellationToken cancellationToken = default) { + timedOut = false; StringBuilder sb = new StringBuilder(); sb.AppendFormat("url={0}\n", repoUrl); sb.AppendFormat("username={0}\n", username); @@ -328,10 +336,13 @@ public virtual bool TryStoreCredential(ITracer tracer, string repoUrl, string us Result result = this.InvokeGitAgainstDotGitFolderOrOutsideEnlistment( GenerateCredentialVerbCommand("approve"), stdin => stdin.Write(stdinConfig), - usePreCommandHook: false); + usePreCommandHook: false, + timeoutMs: timeoutMs, + cancellationToken: cancellationToken); if (result.ExitCodeIsFailure) { + timedOut = IsTimeoutResult(result); tracer.RelatedWarning("Git could not approve credentials: {0}", result.Errors); errorMessage = result.Errors; @@ -342,6 +353,11 @@ public virtual bool TryStoreCredential(ITracer tracer, string repoUrl, string us return true; } + private static bool IsTimeoutResult(Result result) + { + return result.TimedOut; + } + /// /// Input for certificate credentials looks like /// protocol=cert @@ -418,11 +434,34 @@ public virtual bool TryGetCredential( out string username, out string password, out string errorMessage, - int timeoutMs = -1) + int timeoutMs = -1, + CancellationToken cancellationToken = default) + { + return this.TryGetCredential( + tracer, + repoUrl, + out username, + out password, + out errorMessage, + out _, + timeoutMs, + cancellationToken); + } + + public virtual bool TryGetCredential( + ITracer tracer, + string repoUrl, + out string username, + out string password, + out string errorMessage, + out bool timedOut, + int timeoutMs = -1, + CancellationToken cancellationToken = default) { username = null; password = null; errorMessage = null; + timedOut = false; using (ITracer activity = tracer.StartActivity(nameof(this.TryGetCredential), EventLevel.Informational)) { @@ -442,7 +481,8 @@ public virtual bool TryGetCredential( usePreCommandHook: false, timeoutMs: timeoutMs, mayRequireAuth: true, - hasVisibleConsoleWindow: hasVisibleConsoleWindow); + hasVisibleConsoleWindow: hasVisibleConsoleWindow, + cancellationToken: cancellationToken); if (gitCredentialOutput.ExitCodeIsFailure) { @@ -454,14 +494,30 @@ public virtual bool TryGetCredential( // repo-local credential.helper) was visible to git. errorData.Add(nameof(usedDotGitFolder), usedDotGitFolder); - if (gitCredentialOutput.Errors.StartsWith("Operation timed out")) + if (gitCredentialOutput.TimedOut) { + timedOut = true; errorMessage = "Credential manager did not respond within " + (timeoutMs / 1000) + " seconds"; - tracer.RelatedWarning( + + // Structured fields (not just message text) so the rate of this bound + // firing can be measured, and so a timeout can be correlated with a + // later successful fetch to tell "prevented a hang" apart from + // "cut off a prompt the user was about to answer". + errorData.Add("Area", nameof(GitProcess)); + errorData.Add("Method", nameof(this.TryGetCredential)); + errorData.Add("timeoutMs", timeoutMs); + if (Uri.TryCreate(repoUrl, UriKind.Absolute, out Uri repoUri)) + { + errorData.Add("RepoAuthority", repoUri.Authority); + } + + tracer.RelatedEvent( + EventLevel.Warning, + "CredentialFetchTimedOut", errorData, - "Git credential fill timed out after " + timeoutMs + "ms", Keywords.Network | Keywords.Telemetry); TraceCredentialFillErrorOutput(tracer, gitCredentialOutput.Errors); + tracer.RelatedWarning(errorData, errorMessage); } else { @@ -1233,7 +1289,8 @@ protected virtual Result InvokeGitImpl( bool usePreCommandHook = true, Action parseStdOutToken = null, bool mayRequireAuth = false, - bool? hasVisibleConsoleWindow = null) + bool? hasVisibleConsoleWindow = null, + CancellationToken cancellationToken = default) { if (failedToSetEncoding && writeStdIn != null) { @@ -1262,6 +1319,8 @@ protected virtual Result InvokeGitImpl( // Result so callers of correctness-critical commands can fail safe. BoundedGitOutputBuffer output = new BoundedGitOutputBuffer(MaxCapturedStdOutChars); BoundedGitOutputBuffer errors = new BoundedGitOutputBuffer(MaxCapturedStdErrChars); + ManualResetEventSlim outputReadCompleted = new ManualResetEventSlim(parseStdOutToken != null); + ManualResetEventSlim errorReadCompleted = new ManualResetEventSlim(false); this.executingProcess.ErrorDataReceived += (sender, args) => { @@ -1269,6 +1328,10 @@ protected virtual Result InvokeGitImpl( { errors.AppendLine(args.Data); } + else + { + errorReadCompleted.Set(); + } }; // In NUL-delimited streaming mode we read stdout ourselves (below) rather than using @@ -1288,6 +1351,10 @@ protected virtual Result InvokeGitImpl( output.AppendLine(args.Data); } } + else + { + outputReadCompleted.Set(); + } }; } @@ -1393,13 +1460,10 @@ protected virtual Result InvokeGitImpl( watchdog?.Dispose(); } - // stdout is at EOF, so git is normally about to exit. Bound this final wait: - // neither the watchdog (now disposed) nor a caller timeout covers it, so a - // wedged git or a partially-successful tree-kill (a surviving grandchild still - // holding the pipe) would otherwise pin this thread forever - the exact - // maintenance/prefetch hang this change is meant to avoid. Reuse the caller's - // timeout as the grace when one was set, otherwise a generous fixed ceiling. + // Reuse the caller's timeout as the post-EOF grace when one was set. + // Otherwise, use a fixed ceiling. int postReadGraceMs = timeoutMs != Timeout.Infinite ? timeoutMs : DefaultPostReadGraceMs; + Stopwatch postReadStopwatch = Stopwatch.StartNew(); if (!this.WaitForExitWithCancellation(postReadGraceMs, out bool _)) { // git is still alive after stdout closed. Kill the tree again and fail @@ -1414,27 +1478,84 @@ protected virtual Result InvokeGitImpl( // Distinct, self-identifying message so a field occurrence is measurable // through the caller's error logging (GitProcess has no tracer of its own). - return new Result(string.Empty, "GitProcess streaming read: git did not exit within " + postReadGraceMs + "ms after stdout closed; killed process tree. " + errors.ToString(), Result.GenericFailureCode, outputTruncated: false, errorsTruncated: errors.Truncated); + return new Result(string.Empty, "GitProcess streaming read: git did not exit within " + postReadGraceMs + "ms after stdout closed; killed process tree. " + errors.ToString(), Result.GenericFailureCode, outputTruncated: false, errorsTruncated: errors.Truncated, timedOut: true); } - // git has exited, so this parameterless WaitForExit() is now instant and - // guarantees the async stderr readers have flushed before we read Errors. - this.executingProcess.WaitForExit(); + int drainTimeoutMs = GetRemainingTimeoutMs(postReadGraceMs, postReadStopwatch); + if (!WaitForOutputDrain(outputReadCompleted, errorReadCompleted, drainTimeoutMs, cancellationToken, out bool drainCanceled)) + { + string terminationError = this.TryKillExecutingProcessTree(); + this.CancelAsyncOutputReads(cancelOutput: false); + if (drainCanceled) + { + throw new OperationCanceledException(cancellationToken); + } + + return new Result( + string.Empty, + "GitProcess streaming read: output did not close within " + postReadGraceMs + "ms after stdout closed. " + terminationError + errors.ToString(), + Result.GenericFailureCode, + outputTruncated: false, + errorsTruncated: errors.Truncated, + timedOut: true); + } if (killedByTimeout) { - return new Result(string.Empty, "Operation timed out: " + errors.ToString(), Result.GenericFailureCode, outputTruncated: false, errorsTruncated: errors.Truncated); + return new Result(string.Empty, "Operation timed out: " + errors.ToString(), Result.GenericFailureCode, outputTruncated: false, errorsTruncated: errors.Truncated, timedOut: true); } } else { this.executingProcess.BeginOutputReadLine(); - if (!this.executingProcess.WaitForExit(timeoutMs)) + Stopwatch processWaitStopwatch = Stopwatch.StartNew(); + if (!this.WaitForExitWithCancellation(timeoutMs, out bool cancellationRequested, cancellationToken)) { - this.executingProcess.Kill(); + lock (this.processLock) + { + if (this.executingProcess != null) + { + GVFSPlatform.Instance.TryKillProcessTree(this.executingProcess.Id, out int _, out string _); + } + } + + Stopwatch killWaitStopwatch = Stopwatch.StartNew(); + if (this.WaitForExitWithCancellation(ProcessKillTimeoutMs, out bool _)) + { + int killDrainTimeoutMs = GetRemainingTimeoutMs(ProcessKillTimeoutMs, killWaitStopwatch); + if (!WaitForOutputDrain(outputReadCompleted, errorReadCompleted, killDrainTimeoutMs, cancellationToken, out bool killDrainCanceled)) + { + this.CancelAsyncOutputReads(cancelOutput: true); + cancellationRequested |= killDrainCanceled; + } + } + + if (cancellationRequested) + { + throw new OperationCanceledException(cancellationToken); + } + + return new Result(output.ToString(), "Operation timed out: " + errors.ToString(), Result.GenericFailureCode, output.Truncated, errors.Truncated, timedOut: true); + } + + int drainTimeoutMs = GetRemainingTimeoutMs(timeoutMs, processWaitStopwatch); + if (!WaitForOutputDrain(outputReadCompleted, errorReadCompleted, drainTimeoutMs, cancellationToken, out bool drainCanceled)) + { + string terminationError = this.TryKillExecutingProcessTree(); + this.CancelAsyncOutputReads(cancelOutput: true); + if (drainCanceled) + { + throw new OperationCanceledException(cancellationToken); + } - return new Result(output.ToString(), "Operation timed out: " + errors.ToString(), Result.GenericFailureCode, output.Truncated, errors.Truncated); + return new Result( + output.ToString(), + "Operation timed out while draining git output: " + terminationError + errors.ToString(), + Result.GenericFailureCode, + output.Truncated, + errors.Truncated, + timedOut: true); } } } @@ -1452,13 +1573,75 @@ protected virtual Result InvokeGitImpl( } } + private static int GetRemainingTimeoutMs(int timeoutMs, Stopwatch stopwatch) + { + if (timeoutMs < 0) + { + return Timeout.Infinite; + } + + return (int)Math.Max(0, timeoutMs - stopwatch.ElapsedMilliseconds); + } + + internal static bool WaitForOutputDrain( + ManualResetEventSlim outputReadCompleted, + ManualResetEventSlim errorReadCompleted, + int timeoutMs, + CancellationToken cancellationToken, + out bool cancellationRequested) + { + cancellationRequested = false; + Stopwatch stopwatch = Stopwatch.StartNew(); + + while (!outputReadCompleted.IsSet || !errorReadCompleted.IsSet) + { + if (cancellationToken.IsCancellationRequested) + { + cancellationRequested = true; + return false; + } + + if (timeoutMs >= 0 && stopwatch.ElapsedMilliseconds >= timeoutMs) + { + return false; + } + + Thread.Sleep(OutputDrainPollIntervalMs); + } + + return true; + } + + private void CancelAsyncOutputReads(bool cancelOutput) + { + if (cancelOutput) + { + try + { + this.executingProcess.CancelOutputRead(); + } + catch (InvalidOperationException) + { + // The async read already completed or was never started. + } + } + + try + { + this.executingProcess.CancelErrorRead(); + } + catch (InvalidOperationException) + { + // The async read already completed or was never started. + } + } + /// /// Waits up to (or indefinitely when negative) for /// to exit. When can be /// canceled, polls at a short interval so a cancellation (e.g. mount shutdown) is observed /// promptly, since has no cancellation-aware overload; - /// otherwise it waits in a single call. Shared by the streaming and buffered paths so both bound - /// their waits identically. + /// otherwise it waits in a single call. /// /// True if the process exited; false if it timed out or was canceled (the caller should kill it). private bool WaitForExitWithCancellation(int timeoutMs, out bool cancellationRequested, CancellationToken cancellationToken = default) @@ -1500,6 +1683,24 @@ private bool WaitForExitWithCancellation(int timeoutMs, out bool cancellationReq } } + private string TryKillExecutingProcessTree() + { + lock (this.processLock) + { + if (this.executingProcess == null) + { + return string.Empty; + } + + if (!GVFSPlatform.Instance.TryKillProcessTree(this.executingProcess.Id, out int exitCode, out string error)) + { + return $"Process tree termination failed with exit code {exitCode}: {error}. "; + } + + return string.Empty; + } + } + private static string GenerateCredentialVerbCommand(string verb) { return $"-c {GitConfigSetting.CredentialUseHttpPath}=true credential {verb}"; @@ -1713,7 +1914,8 @@ private Result InvokeGitOutsideEnlistment( int timeout = -1, bool usePreCommandHook = true, bool mayRequireAuth = false, - bool? hasVisibleConsoleWindow = null) + bool? hasVisibleConsoleWindow = null, + CancellationToken cancellationToken = default) { return this.InvokeGitImpl( command, @@ -1725,7 +1927,8 @@ private Result InvokeGitOutsideEnlistment( timeoutMs: timeout, usePreCommandHook: usePreCommandHook, mayRequireAuth: mayRequireAuth, - hasVisibleConsoleWindow: hasVisibleConsoleWindow); + hasVisibleConsoleWindow: hasVisibleConsoleWindow, + cancellationToken: cancellationToken); } /// @@ -1752,7 +1955,8 @@ private Result InvokeGitAgainstDotGitFolderOrOutsideEnlistment( bool usePreCommandHook = true, int timeoutMs = -1, bool mayRequireAuth = false, - bool? hasVisibleConsoleWindow = null) + bool? hasVisibleConsoleWindow = null, + CancellationToken cancellationToken = default) { return this.InvokeGitAgainstDotGitFolderOrOutsideEnlistment( command, @@ -1762,7 +1966,8 @@ private Result InvokeGitAgainstDotGitFolderOrOutsideEnlistment( usePreCommandHook, timeoutMs, mayRequireAuth, - hasVisibleConsoleWindow); + hasVisibleConsoleWindow, + cancellationToken); } /// @@ -1780,7 +1985,8 @@ private Result InvokeGitAgainstDotGitFolderOrOutsideEnlistment( bool usePreCommandHook = true, int timeoutMs = -1, bool mayRequireAuth = false, - bool? hasVisibleConsoleWindow = null) + bool? hasVisibleConsoleWindow = null, + CancellationToken cancellationToken = default) { // Evaluate once so the reported route always matches the route taken. usedDotGitFolder = this.DotGitRootExists(); @@ -1794,7 +2000,8 @@ private Result InvokeGitAgainstDotGitFolderOrOutsideEnlistment( usePreCommandHook: usePreCommandHook, timeoutMs: timeoutMs, mayRequireAuth: mayRequireAuth, - hasVisibleConsoleWindow: hasVisibleConsoleWindow); + hasVisibleConsoleWindow: hasVisibleConsoleWindow, + cancellationToken: cancellationToken); } return this.InvokeGitOutsideEnlistment( @@ -1804,7 +2011,8 @@ private Result InvokeGitAgainstDotGitFolderOrOutsideEnlistment( timeout: timeoutMs, usePreCommandHook: usePreCommandHook, mayRequireAuth: mayRequireAuth, - hasVisibleConsoleWindow: hasVisibleConsoleWindow); + hasVisibleConsoleWindow: hasVisibleConsoleWindow, + cancellationToken: cancellationToken); } /// @@ -1861,7 +2069,8 @@ private Result InvokeGitAgainstDotGitFolder( string gitObjectsDirectory = null, int timeoutMs = -1, bool mayRequireAuth = false, - bool? hasVisibleConsoleWindow = null) + bool? hasVisibleConsoleWindow = null, + CancellationToken cancellationToken = default) { // This git command should not need/use the working directory of the repo. // Run git.exe in Environment.SystemDirectory to ensure the git.exe process @@ -1877,7 +2086,8 @@ private Result InvokeGitAgainstDotGitFolder( gitObjectsDirectory: gitObjectsDirectory, usePreCommandHook: usePreCommandHook, mayRequireAuth: mayRequireAuth, - hasVisibleConsoleWindow: hasVisibleConsoleWindow); + hasVisibleConsoleWindow: hasVisibleConsoleWindow, + cancellationToken: cancellationToken); } public class Result @@ -1890,18 +2100,20 @@ public Result(string stdout, string stderr, int exitCode) { } - public Result(string stdout, string stderr, int exitCode, bool outputTruncated, bool errorsTruncated) + public Result(string stdout, string stderr, int exitCode, bool outputTruncated, bool errorsTruncated, bool timedOut = false) { this.Output = stdout; this.Errors = stderr; this.ExitCode = exitCode; this.OutputTruncated = outputTruncated; this.ErrorsTruncated = errorsTruncated; + this.TimedOut = timedOut; } public string Output { get; } public string Errors { get; } public int ExitCode { get; } + public bool TimedOut { get; } /// /// True if the git process produced more stdout than the capture buffer allowed, so diff --git a/GVFS/GVFS.Common/Git/ICredentialStore.cs b/GVFS/GVFS.Common/Git/ICredentialStore.cs index 9ab38e13d..6c0bc542e 100644 --- a/GVFS/GVFS.Common/Git/ICredentialStore.cs +++ b/GVFS/GVFS.Common/Git/ICredentialStore.cs @@ -1,13 +1,14 @@ using GVFS.Common.Tracing; +using System.Threading; namespace GVFS.Common.Git { public interface ICredentialStore { - bool TryGetCredential(ITracer tracer, string url, out string username, out string password, out string error, int timeoutMs = -1); + bool TryGetCredential(ITracer tracer, string url, out string username, out string password, out string error, out bool timedOut, int timeoutMs = -1, CancellationToken cancellationToken = default); - bool TryStoreCredential(ITracer tracer, string url, string username, string password, out string error); + bool TryStoreCredential(ITracer tracer, string url, string username, string password, out string error, out bool timedOut, int timeoutMs = -1, CancellationToken cancellationToken = default); - bool TryDeleteCredential(ITracer tracer, string url, string username, string password, out string error); + bool TryDeleteCredential(ITracer tracer, string url, string username, string password, out string error, out bool timedOut, int timeoutMs = -1, CancellationToken cancellationToken = default); } } diff --git a/GVFS/GVFS.Common/Http/GitEndPointResponseData.cs b/GVFS/GVFS.Common/Http/GitEndPointResponseData.cs index 0be18adc0..556a35bc5 100644 --- a/GVFS/GVFS.Common/Http/GitEndPointResponseData.cs +++ b/GVFS/GVFS.Common/Http/GitEndPointResponseData.cs @@ -23,12 +23,14 @@ public GitEndPointResponseData( bool shouldRetry, HttpResponseMessage message, Action onResponseDisposed, - bool shouldRecordFailure = true) + bool shouldRecordFailure = true, + bool credentialFetchTimedOut = false) { this.StatusCode = statusCode; this.Error = error; this.ShouldRetry = shouldRetry; this.ShouldRecordFailure = shouldRetry && shouldRecordFailure; + this.CredentialFetchTimedOut = credentialFetchTimedOut; this.message = message; this.onResponseDisposed = onResponseDisposed; } @@ -49,6 +51,8 @@ public GitEndPointResponseData(HttpStatusCode statusCode, string contentType, St public bool ShouldRecordFailure { get; } + public bool CredentialFetchTimedOut { get; } + public HttpStatusCode StatusCode { get; } public Stream Stream { get; private set; } diff --git a/GVFS/GVFS.Common/Http/GitObjectsHttpRequestor.cs b/GVFS/GVFS.Common/Http/GitObjectsHttpRequestor.cs index 80d64030e..b2c54cddc 100644 --- a/GVFS/GVFS.Common/Http/GitObjectsHttpRequestor.cs +++ b/GVFS/GVFS.Common/Http/GitObjectsHttpRequestor.cs @@ -82,7 +82,10 @@ public virtual List QueryForFileSizes(IEnumerable objectI { using (GitEndPointResponseData response = this.SendProtocolRequest(requestId, gvfsEndpoint, HttpMethod.Post, objectIdsJson, cancellationToken)) { - if (response.HasErrors && !useGlobalCacheServer && !useOrigin) + if (response.HasErrors && + !response.CredentialFetchTimedOut && + !useGlobalCacheServer && + !useOrigin) { this.TraceCacheServerFallback( requestId, @@ -430,7 +433,10 @@ public virtual RetryWrapper.InvocationResult TrySendProtoco { if (response.HasErrors) { - bool shouldFallBack = hasFallbackEndPoint && !useFallbackEndPoint; + bool shouldFallBack = ShouldFallBackToGlobalEndpoint( + hasFallbackEndPoint, + useFallbackEndPoint, + response); if (shouldFallBack) { this.TraceCacheServerFallback( @@ -445,7 +451,7 @@ public virtual RetryWrapper.InvocationResult TrySendProtoco return new RetryWrapper.CallbackResult( response.Error, shouldFallBack || response.ShouldRetry, - new GitObjectTaskResult(response.StatusCode, requestEndPoint), + new GitObjectTaskResult(response.StatusCode, requestEndPoint, response.CredentialFetchTimedOut), shouldRecordFailure: response.ShouldRecordFailure && !shouldFallBack); } @@ -500,6 +506,16 @@ public virtual RetryWrapper.InvocationResult TrySendProtoco }); } + internal static bool ShouldFallBackToGlobalEndpoint( + bool hasFallbackEndPoint, + bool useFallbackEndPoint, + GitEndPointResponseData response) + { + return hasFallbackEndPoint && + !useFallbackEndPoint && + !response.CredentialFetchTimedOut; + } + private RetryWrapper.CallbackResult HandleProtocolException( long requestId, Exception error, @@ -621,21 +637,24 @@ public GitObjectTaskResult(bool success, Uri requestUri = null) this.RequestUri = requestUri; } - public GitObjectTaskResult(HttpStatusCode statusCode, Uri requestUri = null) + public GitObjectTaskResult(HttpStatusCode statusCode, Uri requestUri = null, bool credentialOperationTimedOut = false) : this(statusCode == HttpStatusCode.OK, requestUri) { this.HttpStatusCodeResult = statusCode; + this.CredentialOperationTimedOut = credentialOperationTimedOut; } public bool Success { get; } public HttpStatusCode HttpStatusCodeResult { get; private set; } public Uri RequestUri { get; } + public bool CredentialOperationTimedOut { get; private set; } public GitObjectTaskResult WithRequestUri(Uri requestUri) { return new GitObjectTaskResult(this.Success, requestUri) { HttpStatusCodeResult = this.HttpStatusCodeResult, + CredentialOperationTimedOut = this.CredentialOperationTimedOut, }; } } diff --git a/GVFS/GVFS.Common/Http/HttpRequestor.cs b/GVFS/GVFS.Common/Http/HttpRequestor.cs index 4ea8e41d5..19c43b324 100644 --- a/GVFS/GVFS.Common/Http/HttpRequestor.cs +++ b/GVFS/GVFS.Common/Http/HttpRequestor.cs @@ -21,6 +21,7 @@ public abstract class HttpRequestor : IDisposable private static long requestCount = 0; private static SemaphoreSlim availableConnections; + private static readonly object connectionConfigurationLock = new object(); private static int connectionLimitConfigured = 0; private readonly ProductInfoHeaderValue userAgentHeader; @@ -61,9 +62,13 @@ internal HttpRequestor( // On first instantiation, check git config for a custom connection limit. // This runs before any requests are made (during mount initialization). - if (Interlocked.CompareExchange(ref connectionLimitConfigured, 1, 0) == 0) + lock (connectionConfigurationLock) { - TryApplyConnectionLimitFromConfig(tracer, enlistment); + if (connectionLimitConfigured == 0) + { + TryApplyConnectionLimitFromConfig(tracer, enlistment); + connectionLimitConfigured = 1; + } } HttpMessageHandler handler = handlerOverride; @@ -103,6 +108,23 @@ internal HttpRequestor( protected ITracer Tracer { get; } + /// + /// Number of currently-available connection-pool permits. Test-only observability hook + /// for asserting that releases its slot at the right time. + /// + internal static int AvailableConnectionCount => availableConnections.CurrentCount; + + // Runtime credential fetches (object/pack downloads, incl. background + // maintenance prefetch) are bounded so a missed/ignored credential prompt + // can't hang forever. The bound is generous (RetryConfig's 120s default) + // rather than the 30s default: this same requestor is shared by interactive + // on-demand hydration and by the user-initiated prefetch/clone verbs, where + // a human may legitimately take longer than 30s to answer a GCM cold-start / + // MFA / smartcard prompt. 120s still bounds the hang while being long enough + // that a noticed prompt is not cut off spuriously. The value comes from the + // already-loaded RetryConfig so no config read happens per requestor. + protected virtual int CredentialTimeoutMs => this.RetryConfig.CredentialTimeoutMs; + public static long GetNewRequestId() { return Interlocked.Increment(ref requestCount); @@ -136,14 +158,22 @@ protected GitEndPointResponseData SendRequest( string errorMessage; if (!sendAnonymous) { - if (!this.authentication.TryGetCredentials(this.Tracer, out authString, out errorMessage)) + if (!this.authentication.TryGetCredentials( + this.Tracer, + out authString, + out errorMessage, + out bool credentialFetchTimedOut, + this.CredentialTimeoutMs, + cancellationToken)) { return new GitEndPointResponseData( HttpStatusCode.Unauthorized, new GitObjectsHttpException(HttpStatusCode.Unauthorized, errorMessage), - shouldRetry: true, + shouldRetry: !credentialFetchTimedOut, message: null, - onResponseDisposed: null); + onResponseDisposed: null, + shouldRecordFailure: !credentialFetchTimedOut, + credentialFetchTimedOut: credentialFetchTimedOut); } // Initialization may finish anonymously while this request waits. @@ -207,6 +237,10 @@ protected GitEndPointResponseData SendRequest( GitEndPointResponseData gitEndPointResponseData = null; HttpResponseMessage response = null; + // Tracks whether the connection-pool slot was released before credential rejection. + // The finally block must not release it a second time. + bool connectionReleasedEarly = false; + try { requestStopwatch.Restart(); @@ -238,7 +272,7 @@ protected GitEndPointResponseData SendRequest( if (!sendAnonymous) { - this.authentication.ApproveCredentials(this.Tracer, authString); + this.authentication.ApproveCredentials(this.Tracer, authString, this.CredentialTimeoutMs, cancellationToken); } else if (!forceAnonymous) { @@ -257,10 +291,12 @@ protected GitEndPointResponseData SendRequest( else { errorMessage = response.Content.ReadAsStringAsync().GetAwaiter().GetResult(); - int statusInt = (int)response.StatusCode; + HttpStatusCode statusCode = response.StatusCode; + int statusInt = (int)statusCode; bool shouldRetry = ShouldRetry(response.StatusCode); bool shouldRecordFailure = shouldRetry; + bool credentialOperationTimedOut = false; if (sendAnonymous && ShouldRejectCredentials(response.StatusCode, errorMessage)) @@ -294,28 +330,46 @@ protected GitEndPointResponseData SendRequest( } else if (ShouldRejectCredentials(response.StatusCode, errorMessage)) { - this.authentication.RejectCredentials(this.Tracer, authString); - if (!this.authentication.IsBackingOff) + // The response body is buffered, so the network operation is complete. + // Release the process-wide permit before the credential helper runs so a + // slow rejection cannot starve unrelated requests. + response.Dispose(); + response = null; + availableConnections.Release(); + connectionReleasedEarly = true; + + credentialOperationTimedOut = this.authentication.RejectCredentials(this.Tracer, authString, this.CredentialTimeoutMs, cancellationToken); + if (credentialOperationTimedOut) { - errorMessage = string.Format("Server returned error code {0} ({1}). Your PAT may be expired and we are asking for a new one. Original error message from server: {2}", statusInt, response.StatusCode, errorMessage); + shouldRetry = false; + errorMessage = string.Format( + "Credential rejection timed out while handling server error code {0} ({1}). Original error message from server: {2}", + statusInt, + statusCode, + errorMessage); + } + else if (!this.authentication.IsBackingOff) + { + errorMessage = string.Format("Server returned error code {0} ({1}). Your PAT may be expired and we are asking for a new one. Original error message from server: {2}", statusInt, statusCode, errorMessage); } else { - errorMessage = string.Format("Server returned error code {0} ({1}) after successfully renewing your PAT. You may not have access to this repo. Original error message from server: {2}", statusInt, response.StatusCode, errorMessage); + errorMessage = string.Format("Server returned error code {0} ({1}) after successfully renewing your PAT. You may not have access to this repo. Original error message from server: {2}", statusInt, statusCode, errorMessage); } } else { - errorMessage = string.Format("Server returned error code {0} ({1}). Original error message from server: {2}", statusInt, response.StatusCode, errorMessage); + errorMessage = string.Format("Server returned error code {0} ({1}). Original error message from server: {2}", statusInt, statusCode, errorMessage); } gitEndPointResponseData = new GitEndPointResponseData( - response.StatusCode, - new GitObjectsHttpException(response.StatusCode, errorMessage), + statusCode, + new GitObjectsHttpException(statusCode, errorMessage), shouldRetry, - message: response, - onResponseDisposed: () => availableConnections.Release(), - shouldRecordFailure: shouldRecordFailure); + message: connectionReleasedEarly ? null : response, + onResponseDisposed: connectionReleasedEarly ? (Action)null : () => availableConnections.Release(), + shouldRecordFailure: shouldRecordFailure, + credentialFetchTimedOut: credentialOperationTimedOut); } } catch (TaskCanceledException) @@ -365,7 +419,12 @@ protected GitEndPointResponseData SendRequest( response.Dispose(); } - availableConnections.Release(); + // Don't release a second time if the connection slot was already freed + // early before a reject leg that then threw (e.g. on cancellation). + if (!connectionReleasedEarly) + { + availableConnections.Release(); + } } } @@ -548,5 +607,6 @@ private static void TryApplyConnectionLimitFromConfig(ITracer tracer, Enlistment tracer.RelatedWarning(metadata, "HttpRequestor: Failed to read gvfs.max-http-connections config, using default"); } } + } } diff --git a/GVFS/GVFS.Common/RetryConfig.cs b/GVFS/GVFS.Common/RetryConfig.cs index 4462a18bc..18672e7ee 100644 --- a/GVFS/GVFS.Common/RetryConfig.cs +++ b/GVFS/GVFS.Common/RetryConfig.cs @@ -11,6 +11,16 @@ public class RetryConfig public const int DefaultTimeoutSeconds = 30; public const int FetchAndCloneTimeoutMinutes = 10; + /// + /// Default bound for a runtime credential fetch. Deliberately generous: the mount's + /// requestor is shared by the background maintenance prefetch, interactive on-demand + /// hydration, and the user-initiated prefetch/clone verbs, where a human may take + /// longer than the 30s request timeout to answer a GCM cold-start / MFA / smartcard + /// prompt. It still bounds the indefinite hang. + /// + public const int DefaultCredentialTimeoutSeconds = 120; + public const int MaxCredentialTimeoutSeconds = int.MaxValue / 1000; + private const string EtwArea = nameof(RetryConfig); private const int MinRetries = 0; @@ -23,9 +33,15 @@ public RetryConfig(int maxRetries = DefaultMaxRetries) } public RetryConfig(int maxRetries, TimeSpan timeout) + : this(maxRetries, timeout, DefaultCredentialTimeoutSeconds * 1000) + { + } + + public RetryConfig(int maxRetries, TimeSpan timeout, int credentialTimeoutMs) { this.MaxRetries = maxRetries; this.Timeout = timeout; + this.CredentialTimeoutMs = credentialTimeoutMs; } public int MaxRetries { get; } @@ -36,6 +52,13 @@ public int MaxAttempts public TimeSpan Timeout { get; set; } + /// + /// How long a runtime credential fetch may block waiting on the credential manager. + /// A negative value waits indefinitely, which is the historical behavior and reopens + /// the hang this bound was added to prevent. + /// + public int CredentialTimeoutMs { get; } + public static bool TryLoadFromGitConfig(ITracer tracer, Enlistment enlistment, out RetryConfig retryConfig, out string error) { return TryLoadFromGitConfig(tracer, new GitProcess(enlistment), out retryConfig, out error); @@ -80,7 +103,25 @@ public static bool TryLoadFromGitConfig(ITracer tracer, GitProcess git, out Retr return false; } - retryConfig = new RetryConfig(maxRetries, timeout); + int credentialTimeoutMs; + if (!TryLoadCredentialTimeoutMs(git, out credentialTimeoutMs, out error)) + { + if (tracer != null) + { + tracer.RelatedError( + new EventMetadata + { + { "Area", EtwArea }, + { "maxRetries", maxRetries }, + { "error", error } + }, + "TryLoadConfig: TryLoadCredentialTimeoutMs failed"); + } + + return false; + } + + retryConfig = new RetryConfig(maxRetries, timeout, credentialTimeoutMs); if (tracer != null) { @@ -92,8 +133,10 @@ public static bool TryLoadFromGitConfig(ITracer tracer, GitProcess git, out Retr { "Area", EtwArea }, { "Timeout", retryConfig.Timeout }, { "MaxRetries", retryConfig.MaxRetries }, + { "CredentialTimeoutMs", retryConfig.CredentialTimeoutMs }, { TracingConstants.MessageKey.InfoMessage, "RetryConfigLoaded" } - }); + }, + Keywords.Telemetry); } return true; @@ -129,6 +172,41 @@ private static bool TryLoadTimeout(GitProcess git, out TimeSpan timeout, out str return true; } + /// + /// Reads the credential-fetch bound, in seconds, from git config. A configured value of + /// 0 or less selects an unbounded wait, so this deliberately allows non-positive values + /// rather than treating them as out of range. + /// + private static bool TryLoadCredentialTimeoutMs(GitProcess git, out int credentialTimeoutMs, out string error) + { + credentialTimeoutMs = DefaultCredentialTimeoutSeconds * 1000; + + int credentialTimeoutSeconds; + if (!TryGetFromGitConfig( + git, + GVFSConstants.GitConfig.CredentialTimeoutSeconds, + DefaultCredentialTimeoutSeconds, + int.MinValue, + out credentialTimeoutSeconds, + out error)) + { + return false; + } + + if (credentialTimeoutSeconds > MaxCredentialTimeoutSeconds) + { + error = string.Format( + "Invalid value {0} for setting {1}, value must be less than or equal to {2}", + credentialTimeoutSeconds, + GVFSConstants.GitConfig.CredentialTimeoutSeconds, + MaxCredentialTimeoutSeconds); + return false; + } + + credentialTimeoutMs = credentialTimeoutSeconds <= 0 ? -1 : credentialTimeoutSeconds * 1000; + return true; + } + private static bool TryGetFromGitConfig(GitProcess git, string configName, int defaultValue, int minValue, out int value, out string error) { GitProcess.ConfigResult result = git.GetFromConfig(configName); diff --git a/GVFS/GVFS.Platform.Windows/WindowsPlatform.cs b/GVFS/GVFS.Platform.Windows/WindowsPlatform.cs index a27c98083..1620986e3 100644 --- a/GVFS/GVFS.Platform.Windows/WindowsPlatform.cs +++ b/GVFS/GVFS.Platform.Windows/WindowsPlatform.cs @@ -5,6 +5,7 @@ using GVFS.Platform.Windows.DiskLayoutUpgrades; using Microsoft.Win32; using System; +using System.ComponentModel; using System.Collections.Generic; using System.Collections.ObjectModel; using System.Diagnostics; @@ -31,6 +32,7 @@ public partial class WindowsPlatform : GVFSPlatform // GetAncestor flag GA_ROOTOWNER (3): walk the owner chain to the root owned window. private const uint GA_ROOTOWNER = 3; + private const int ProcessTreeKillTimeoutMs = 5 * 1000; public WindowsPlatform() : base(underConstruction: new UnderConstructionFlags()) { @@ -457,10 +459,47 @@ public override bool TryGetDefaultLocalCacheRoot(string enlistmentRoot, out stri public override bool TryKillProcessTree(int processId, out int exitCode, out string error) { - ProcessResult result = ProcessHelper.Run("taskkill", $"/pid {processId} /f /t"); - error = result.Errors; - exitCode = result.ExitCode; - return result.ExitCode == 0; + try + { + using (Process targetProcess = Process.GetProcessById(processId)) + { + targetProcess.Kill(entireProcessTree: true); + if (!targetProcess.WaitForExit(ProcessTreeKillTimeoutMs)) + { + exitCode = StillActive; + error = $"Process tree {processId} did not exit within {ProcessTreeKillTimeoutMs}ms"; + return false; + } + + exitCode = targetProcess.ExitCode; + error = null; + return true; + } + } + catch (ArgumentException) + { + exitCode = 0; + error = null; + return true; + } + catch (InvalidOperationException) + { + exitCode = 0; + error = null; + return true; + } + catch (Win32Exception e) + { + exitCode = e.NativeErrorCode; + error = e.Message; + return false; + } + catch (AggregateException e) + { + exitCode = -1; + error = e.ToString(); + return false; + } } public override bool TryCopyPanicLogs(string copyToDir, out string error) diff --git a/GVFS/GVFS.UnitTests/Common/Git/GitProcessCredentialTests.cs b/GVFS/GVFS.UnitTests/Common/Git/GitProcessCredentialTests.cs index de15ac1a2..c0eb20ef2 100644 --- a/GVFS/GVFS.UnitTests/Common/Git/GitProcessCredentialTests.cs +++ b/GVFS/GVFS.UnitTests/Common/Git/GitProcessCredentialTests.cs @@ -172,7 +172,8 @@ private string RunCredentialFill(string workingDirectoryRoot) RepoUrl, out string username, out string password, - out string error) + out string error, + out bool _) .ShouldBeTrue(error); gitProcess.CommandsRun.ShouldContain(x => x.StartsWith(CredentialFillCommandPrefix, StringComparison.Ordinal)); @@ -189,7 +190,8 @@ private string RunStoreCredential(string workingDirectoryRoot) RepoUrl, "mockUser", "mockPassword", - out string error) + out string error, + out _) .ShouldBeTrue(error); gitProcess.CommandsRun.ShouldContain(x => x.StartsWith(CredentialApproveCommandPrefix, StringComparison.Ordinal)); @@ -206,7 +208,8 @@ private string RunDeleteCredential(string workingDirectoryRoot) RepoUrl, "mockUser", "mockPassword", - out string error) + out string error, + out _) .ShouldBeTrue(error); gitProcess.CommandsRun.ShouldContain(x => x.StartsWith(CredentialRejectCommandPrefix, StringComparison.Ordinal)); @@ -384,17 +387,41 @@ public void TryGetCredentialKeepsStderrOutOfTelemetryWhenTheCredentialManagerTim { MockTracer tracer = new MockTracer(); string stderr = "Operation timed out after 5000ms; " + SecretValue; - MockGitProcess gitProcess = CreateGitProcess(CredentialFillCommand, string.Empty, stderr, GitProcess.Result.GenericFailureCode); + MockGitProcess gitProcess = CreateGitProcess(CredentialFillCommand, string.Empty, stderr, GitProcess.Result.GenericFailureCode, timedOut: true); gitProcess.TryGetCredential(tracer, "mock://repoUrl", out _, out _, out string errorMessage, timeoutMs: 5000).ShouldBeFalse(); errorMessage.ShouldEqual("Credential manager did not respond within 5 seconds"); - EventMetadata warning = GetTelemetryWarning(tracer); + int timeoutEventIndex = tracer.RelatedEventNames.IndexOf("CredentialFetchTimedOut"); + timeoutEventIndex.ShouldBeAtLeast(0); + EventMetadata warning = tracer.RelatedEventMetadata[timeoutEventIndex]; ((int)warning["ErrorsLength"]).ShouldEqual(stderr.Length); AssertNoSecret(warning); tracer.RelatedWarningEvents.Any(e => e.Contains(SecretValue)).ShouldBeTrue("The local log keeps the captured stderr of a timeout"); } + [TestCase] + public void TryGetCredentialDoesNotInferTimeoutFromStderr() + { + MockTracer tracer = new MockTracer(); + MockGitProcess gitProcess = CreateGitProcess( + CredentialFillCommand, + string.Empty, + "Operation timed out in a credential helper", + GitProcess.Result.GenericFailureCode); + + gitProcess.TryGetCredential( + tracer, + "mock://repoUrl", + out _, + out _, + out _, + out bool timedOut) + .ShouldBeFalse(); + + timedOut.ShouldBeFalse(); + } + [TestCase] public void TryGetCredentialFailsWhenThePasswordIsEmpty() { @@ -454,12 +481,13 @@ private static MockGitProcess CreateGitProcess( string output, string errors = "", int exitCode = GitProcess.Result.SuccessCode, - bool outputTruncated = false) + bool outputTruncated = false, + bool timedOut = false) { MockGitProcess gitProcess = new MockGitProcess(); gitProcess.SetExpectedCommandResult( command, - () => new GitProcess.Result(output, errors, exitCode, outputTruncated, errorsTruncated: false)); + () => new GitProcess.Result(output, errors, exitCode, outputTruncated, errorsTruncated: false, timedOut: timedOut)); return gitProcess; } diff --git a/GVFS/GVFS.UnitTests/Common/RetryConfigTests.cs b/GVFS/GVFS.UnitTests/Common/RetryConfigTests.cs index 0f8c45b26..e4040b15e 100644 --- a/GVFS/GVFS.UnitTests/Common/RetryConfigTests.cs +++ b/GVFS/GVFS.UnitTests/Common/RetryConfigTests.cs @@ -33,6 +33,7 @@ public void TryLoadConfigUsesDefaultValuesWhenEntriesNotInConfig() MockGitProcess gitProcess = new MockGitProcess(); gitProcess.SetExpectedCommandResult("config gvfs.max-retries", () => new GitProcess.Result(string.Empty, string.Empty, GitProcess.Result.GenericFailureCode)); gitProcess.SetExpectedCommandResult("config gvfs.timeout-seconds", () => new GitProcess.Result(string.Empty, string.Empty, GitProcess.Result.GenericFailureCode)); + gitProcess.SetExpectedCommandResult("config gvfs.credential-timeout-seconds", () => new GitProcess.Result(string.Empty, string.Empty, GitProcess.Result.GenericFailureCode)); RetryConfig config; string error; @@ -41,6 +42,7 @@ public void TryLoadConfigUsesDefaultValuesWhenEntriesNotInConfig() config.MaxRetries.ShouldEqual(RetryConfig.DefaultMaxRetries); config.MaxAttempts.ShouldEqual(config.MaxRetries + 1); config.Timeout.ShouldEqual(TimeSpan.FromSeconds(RetryConfig.DefaultTimeoutSeconds)); + config.CredentialTimeoutMs.ShouldEqual(RetryConfig.DefaultCredentialTimeoutSeconds * 1000); } [TestCase] @@ -50,6 +52,7 @@ public void TryLoadConfigUsesDefaultValuesWhenEntriesAreBlank() MockGitProcess gitProcess = new MockGitProcess(); gitProcess.SetExpectedCommandResult("config gvfs.max-retries", () => new GitProcess.Result(string.Empty, string.Empty, GitProcess.Result.SuccessCode)); gitProcess.SetExpectedCommandResult("config gvfs.timeout-seconds", () => new GitProcess.Result(string.Empty, string.Empty, GitProcess.Result.SuccessCode)); + gitProcess.SetExpectedCommandResult("config gvfs.credential-timeout-seconds", () => new GitProcess.Result(string.Empty, string.Empty, GitProcess.Result.SuccessCode)); RetryConfig config; string error; @@ -58,6 +61,7 @@ public void TryLoadConfigUsesDefaultValuesWhenEntriesAreBlank() config.MaxRetries.ShouldEqual(RetryConfig.DefaultMaxRetries); config.MaxAttempts.ShouldEqual(config.MaxRetries + 1); config.Timeout.ShouldEqual(TimeSpan.FromSeconds(RetryConfig.DefaultTimeoutSeconds)); + config.CredentialTimeoutMs.ShouldEqual(RetryConfig.DefaultCredentialTimeoutSeconds * 1000); } [TestCase] @@ -93,11 +97,13 @@ public void TryLoadConfigUsesConfiguredValues() { int maxRetries = RetryConfig.DefaultMaxRetries + 1; int timeoutSeconds = RetryConfig.DefaultTimeoutSeconds + 1; + int credentialTimeoutSeconds = RetryConfig.DefaultCredentialTimeoutSeconds + 1; MockTracer tracer = new MockTracer(); MockGitProcess gitProcess = new MockGitProcess(); gitProcess.SetExpectedCommandResult("config gvfs.max-retries", () => new GitProcess.Result(maxRetries.ToString(), string.Empty, GitProcess.Result.SuccessCode)); gitProcess.SetExpectedCommandResult("config gvfs.timeout-seconds", () => new GitProcess.Result(timeoutSeconds.ToString(), string.Empty, GitProcess.Result.SuccessCode)); + gitProcess.SetExpectedCommandResult("config gvfs.credential-timeout-seconds", () => new GitProcess.Result(credentialTimeoutSeconds.ToString(), string.Empty, GitProcess.Result.SuccessCode)); RetryConfig config; string error; @@ -106,6 +112,61 @@ public void TryLoadConfigUsesConfiguredValues() config.MaxRetries.ShouldEqual(maxRetries); config.MaxAttempts.ShouldEqual(config.MaxRetries + 1); config.Timeout.ShouldEqual(TimeSpan.FromSeconds(timeoutSeconds)); + config.CredentialTimeoutMs.ShouldEqual(credentialTimeoutSeconds * 1000); + } + + [TestCase] + public void TryLoadConfigTreatsNonPositiveCredentialTimeoutAsUnbounded() + { + // A non-positive value is a deliberate escape hatch selecting the historical + // unbounded wait, so it must be accepted rather than rejected as out of range. + MockTracer tracer = new MockTracer(); + MockGitProcess gitProcess = new MockGitProcess(); + gitProcess.SetExpectedCommandResult("config gvfs.max-retries", () => new GitProcess.Result("3", string.Empty, GitProcess.Result.SuccessCode)); + gitProcess.SetExpectedCommandResult("config gvfs.timeout-seconds", () => new GitProcess.Result("30", string.Empty, GitProcess.Result.SuccessCode)); + gitProcess.SetExpectedCommandResult("config gvfs.credential-timeout-seconds", () => new GitProcess.Result("0", string.Empty, GitProcess.Result.SuccessCode)); + + RetryConfig config; + string error; + RetryConfig.TryLoadFromGitConfig(tracer, gitProcess, out config, out error).ShouldEqual(true); + config.CredentialTimeoutMs.ShouldEqual(-1, "0 seconds should select an unbounded wait"); + } + + [TestCase] + public void TryLoadConfigTreatsNegativeCredentialTimeoutAsUnbounded() + { + MockGitProcess gitProcess = this.CreateGitProcessWithCredentialTimeout("-5"); + + RetryConfig.TryLoadFromGitConfig(null, gitProcess, out RetryConfig config, out string error).ShouldBeTrue(error); + config.CredentialTimeoutMs.ShouldEqual(-1, "A negative value should select an unbounded wait"); + } + + [TestCase] + public void TryLoadConfigRejectsCredentialTimeoutThatOverflowsMilliseconds() + { + int tooLarge = RetryConfig.MaxCredentialTimeoutSeconds + 1; + MockGitProcess gitProcess = this.CreateGitProcessWithCredentialTimeout(tooLarge.ToString()); + + RetryConfig.TryLoadFromGitConfig(null, gitProcess, out _, out string error).ShouldBeFalse(); + error.ShouldContain("less than or equal to"); + } + + [TestCase] + public void RetryConfigDefaultsCredentialTimeoutWhenNotLoadedFromConfig() + { + // Requestors constructed with a hand-built RetryConfig (tests, FastFetch, profiling) + // must still get a bounded credential fetch rather than an unbounded default. + new RetryConfig().CredentialTimeoutMs.ShouldEqual(RetryConfig.DefaultCredentialTimeoutSeconds * 1000); + new RetryConfig(3, TimeSpan.FromSeconds(30)).CredentialTimeoutMs.ShouldEqual(RetryConfig.DefaultCredentialTimeoutSeconds * 1000); + } + + private MockGitProcess CreateGitProcessWithCredentialTimeout(string credentialTimeoutSeconds) + { + MockGitProcess gitProcess = new MockGitProcess(); + gitProcess.SetExpectedCommandResult("config gvfs.max-retries", () => new GitProcess.Result("3", string.Empty, GitProcess.Result.SuccessCode)); + gitProcess.SetExpectedCommandResult("config gvfs.timeout-seconds", () => new GitProcess.Result("30", string.Empty, GitProcess.Result.SuccessCode)); + gitProcess.SetExpectedCommandResult("config gvfs.credential-timeout-seconds", () => new GitProcess.Result(credentialTimeoutSeconds, string.Empty, GitProcess.Result.SuccessCode)); + return gitProcess; } } } diff --git a/GVFS/GVFS.UnitTests/Git/GVFSGitObjectsTests.cs b/GVFS/GVFS.UnitTests/Git/GVFSGitObjectsTests.cs index 0d522bb5c..5acf7c256 100644 --- a/GVFS/GVFS.UnitTests/Git/GVFSGitObjectsTests.cs +++ b/GVFS/GVFS.UnitTests/Git/GVFSGitObjectsTests.cs @@ -183,6 +183,44 @@ public void TerminalBlobHydrationFailureTagsObjectNotOnServer() terminalError.ShouldContain("\"BlobHydrationFailureCategory\":\"ObjectNotOnServer\""); } + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void CredentialTimeoutStopsOuterBlobHydrationRetries() + { + 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 + { + StatusCodeToReturn = HttpStatusCode.Unauthorized, + CredentialOperationTimedOut = true, + }; + GVFSGitObjects dut = this.CreateTestableGVFSGitObjects(httpObjects, fileSystem, out MockTracer tracer); + + dut.TryCopyBlobContentStream( + ValidTestObjectFileSha1, + CancellationToken.None, + GVFSGitObjects.RequestSource.FileStreamCallback, + (stream, length) => Assert.Fail("A timed-out download must not provide blob content"), + out _) + .ShouldBeFalse(); + + httpObjects.TryDownloadObjectsCallCount.ShouldEqual( + 1, + "A credential timeout must stop the current hydration operation instead of entering its outer retry loop"); + string terminalError = tracer.RelatedErrorEvents.First(e => e.Contains("Failed to provide blob contents")); + terminalError.ShouldContain("\"CredentialOperationTimedOut\":true"); + } + [TestCase] [Category(CategoryConstants.ExceptionExpected)] public void TerminalBlobHydrationFailureRecordsHttpStatusCode() @@ -1077,6 +1115,7 @@ private MockHttpGitObjects(MockGVFSEnlistment enlistment) public string MediaType { get; set; } public HttpStatusCode? StatusCodeToReturn { get; set; } public bool ShouldRecordFailureToReturn { get; set; } = true; + public bool CredentialOperationTimedOut { get; set; } // When true, TryDownloadObjects returns a failing result built from GitObjectTaskResult(bool), // i.e. Result is non-null but carries no HTTP status (HttpStatusCodeResult == 0). This @@ -1127,7 +1166,9 @@ public override RetryWrapper.InvocationResult TryDownloadOb return new RetryWrapper.InvocationResult( 0, error: null, - result: new GitObjectTaskResult(this.StatusCodeToReturn.Value), + result: new GitObjectTaskResult( + this.StatusCodeToReturn.Value, + credentialOperationTimedOut: this.CredentialOperationTimedOut), shouldRecordFailure: this.ShouldRecordFailureToReturn); } diff --git a/GVFS/GVFS.UnitTests/Git/GitAuthenticationTests.cs b/GVFS/GVFS.UnitTests/Git/GitAuthenticationTests.cs index 499557771..79a282090 100644 --- a/GVFS/GVFS.UnitTests/Git/GitAuthenticationTests.cs +++ b/GVFS/GVFS.UnitTests/Git/GitAuthenticationTests.cs @@ -13,6 +13,7 @@ using GVFS.Common.Tracing; using GVFS.Tests; using GVFS.Tests.Should; +using GVFS.UnitTests.Category; using GVFS.UnitTests.Mock.Common; using GVFS.UnitTests.Mock.Git; using GVFS.UnitTests.Mock.Http; @@ -591,7 +592,7 @@ public void TryGetCredentialLogsConsoleVisibilityWhenCredentialFillFails() MockGitProcess gitProcess = new MockGitProcess(); gitProcess.SetExpectedCommandResult( $"{AzureDevOpsUseHttpPathString} credential fill", - () => new GitProcess.Result(string.Empty, "Operation timed out waiting for a response", GitProcess.Result.GenericFailureCode)); + () => new GitProcess.Result(string.Empty, "Operation timed out waiting for a response", GitProcess.Result.GenericFailureCode, false, false, timedOut: true)); gitProcess.TryGetCredential(tracer, "mock://repoUrl", out string username, out string password, out string error, timeoutMs: 5000) .ShouldEqual(false, "Credential fill should report failure when git times out"); @@ -627,7 +628,7 @@ public void TryGetCertificatePasswordLogsConsoleVisibilityWhenCredentialFillFail MockGitProcess gitProcess = new MockGitProcess(); gitProcess.SetExpectedCommandResult( "credential fill", - () => new GitProcess.Result(string.Empty, "Operation timed out waiting for a response", GitProcess.Result.GenericFailureCode)); + () => new GitProcess.Result(string.Empty, "Operation timed out waiting for a response", GitProcess.Result.GenericFailureCode, false, false, timedOut: true)); gitProcess.TryGetCertificatePassword(tracer, CertificatePath, out string password, out string error) .ShouldEqual(false, "Certificate password fill should report failure when git times out"); @@ -1076,6 +1077,314 @@ public void AnonymousAuthFailurePromotesWithoutPriorInitialization() .ShouldEqual(true, "Promotion must affect the next request without prior initialization"); } + [TestCase] + public void TryGetCredentialsCancellationInterruptsInitializationWait() + { + MockTracer tracer = new MockTracer(); + GitAuthentication dut = new GitAuthentication(this.GetGitProcess(), "mock://repoUrl") + { + InitializationWaitTimeoutMs = 30_000, + }; + + using (CancellationTokenSource cts = new CancellationTokenSource()) + { + cts.Cancel(); + + Assert.Throws( + () => dut.TryGetCredentials(tracer, out _, out _, cancellationToken: cts.Token)); + } + } + + [TestCase] + public void TryGetCredentialsReportsTimedOutOnlyForTimeouts() + { + MockTracer tracer = new MockTracer(); + MockGitProcess gitProcess = this.GetGitProcess(); + GitAuthentication dut = new GitAuthentication(gitProcess, "mock://repoUrl"); + dut.TryInitializeAndRequireAuth(tracer, out _); + + dut.TryGetCredentials(tracer, out string authString, out string error, out bool timedOut) + .ShouldBeTrue("Initial credential fetch should succeed: " + error); + timedOut.ShouldBeFalse(); + + gitProcess.SetExpectedCommandResult( + $"{AzureDevOpsUseHttpPathString} credential fill", + () => new GitProcess.Result(string.Empty, "fatal: could not read Username", GitProcess.Result.GenericFailureCode), + matchPrefix: true); + + dut.RejectCredentials(tracer, authString); + dut.TryGetCredentials(tracer, out _, out _, out timedOut).ShouldBeFalse(); + timedOut.ShouldBeFalse("A generic credential failure is not a timeout"); + + MockGitProcess timingOutProcess = this.GetGitProcess(); + GitAuthentication timingOutDut = new GitAuthentication(timingOutProcess, "mock://repoUrl"); + timingOutDut.TryInitializeAndRequireAuth(tracer, out _); + timingOutDut.TryGetCredentials(tracer, out string timingOutAuth, out error).ShouldBeTrue(); + timingOutDut.RejectCredentials(tracer, timingOutAuth); + timingOutProcess.SetExpectedCommandResult( + $"{AzureDevOpsUseHttpPathString} credential fill", + () => new GitProcess.Result(string.Empty, "Operation timed out: git credential fill", GitProcess.Result.GenericFailureCode, false, false, timedOut: true), + matchPrefix: true); + + timingOutDut.TryGetCredentials(tracer, out _, out error, out timedOut, credentialTimeoutMs: 1000).ShouldBeFalse(); + timedOut.ShouldBeTrue("A credential manager timeout must be terminal"); + timingOutProcess.LastInvokedTimeoutMs.ShouldEqual(1000); + error.ShouldContain("within 1 seconds"); + } + + [TestCase] + public void RejectCredentialsBoundsReloadAndDeleteToOneDeadline() + { + MockTracer tracer = new MockTracer(); + MockGitProcess gitProcess = this.GetGitProcess(); + GitAuthentication dut = new GitAuthentication(gitProcess, "mock://repoUrl"); + dut.TryInitializeAndRequireAuth(tracer, out _); + dut.TryGetCredentials(tracer, out string authString, out _).ShouldBeTrue(); + + gitProcess.SetExpectedCommandResult( + $"{AzureDevOpsUseHttpPathString} credential fill", + () => + { + Thread.Sleep(150); + return new GitProcess.Result("username=username\r\npassword=password0\r\n", string.Empty, GitProcess.Result.SuccessCode); + }, + matchPrefix: true); + gitProcess.InvokedTimeoutMs.Clear(); + dut.RejectCredentials(tracer, authString, credentialTimeoutMs: 1000); + + gitProcess.InvokedTimeoutMs.Count.ShouldEqual(2); + gitProcess.InvokedTimeoutMs.ShouldNotContain(timeout => timeout < 0); + gitProcess.LastInvokedTimeoutMs.Value.ShouldBeAtLeast(1); + gitProcess.LastInvokedTimeoutMs.Value.ShouldBeAtMost(900); + } + + [TestCase] + public void ApproveCredentialsUsesTimeoutAndProtectsActiveHelperFromCancellation() + { + MockTracer tracer = new MockTracer(); + MockGitProcess gitProcess = this.GetGitProcess(); + GitAuthentication dut = new GitAuthentication(gitProcess, "mock://repoUrl"); + dut.TryInitializeAndRequireAuth(tracer, out _); + dut.TryGetCredentials(tracer, out string authString, out _).ShouldBeTrue(); + + using (CancellationTokenSource cts = new CancellationTokenSource()) + { + dut.ApproveCredentials(tracer, authString, credentialTimeoutMs: 1234, cancellationToken: cts.Token); + + gitProcess.LastInvokedTimeoutMs.ShouldEqual(1234); + gitProcess.LastInvokedCancellationToken.CanBeCanceled.ShouldBeFalse(); + } + } + + [TestCase] + public void ReloadTimeoutIsTerminalAndSkipsDelete() + { + MockTracer tracer = new MockTracer(); + MockGitProcess gitProcess = this.GetGitProcess(); + GitAuthentication dut = new GitAuthentication(gitProcess, "mock://repoUrl"); + dut.TryInitializeAndRequireAuth(tracer, out _); + dut.TryGetCredentials(tracer, out string authString, out _).ShouldBeTrue(); + + gitProcess.SetExpectedCommandResult( + $"{AzureDevOpsUseHttpPathString} credential fill", + () => new GitProcess.Result(string.Empty, "Operation timed out: git credential fill", GitProcess.Result.GenericFailureCode, false, false, timedOut: true), + matchPrefix: true); + int deleteCount = gitProcess.CommandsRun.Count(command => command.Contains("credential reject")); + + dut.RejectCredentials(tracer, authString, credentialTimeoutMs: 1000).ShouldBeTrue(); + + gitProcess.CommandsRun.Count(command => command.Contains("credential reject")).ShouldEqual(deleteCount); + dut.TryGetCredentials(tracer, out _, out _, out bool timedOut).ShouldBeFalse(); + timedOut.ShouldBeTrue("Timeout backoff must remain terminal"); + } + + [TestCase] + public void DeleteTimeoutIsTerminal() + { + MockTracer tracer = new MockTracer(); + MockGitProcess gitProcess = this.GetGitProcess(); + GitAuthentication dut = new GitAuthentication(gitProcess, "mock://repoUrl"); + dut.TryInitializeAndRequireAuth(tracer, out _); + dut.TryGetCredentials(tracer, out string authString, out _).ShouldBeTrue(); + + gitProcess.SetExpectedCommandResult( + $"{AzureDevOpsUseHttpPathString} credential reject", + () => new GitProcess.Result(string.Empty, "Operation timed out: git credential reject", GitProcess.Result.GenericFailureCode, false, false, timedOut: true), + matchPrefix: true); + + dut.RejectCredentials(tracer, authString, credentialTimeoutMs: 1000).ShouldBeTrue(); + dut.TryGetCredentials(tracer, out _, out _, out bool timedOut).ShouldBeFalse(); + timedOut.ShouldBeTrue("Delete timeout backoff must remain terminal"); + } + + [TestCase] + public void ActiveCredentialFillIgnoresPerRequestCancellation() + { + MockTracer tracer = new MockTracer(); + MockGitProcess gitProcess = this.GetGitProcess(); + GitAuthentication dut = new GitAuthentication(gitProcess, "mock://repoUrl"); + dut.TryInitializeAndRequireAuth(tracer, out _); + dut.TryGetCredentials(tracer, out string authString, out _).ShouldBeTrue(); + dut.RejectCredentials(tracer, authString); + + using (ManualResetEventSlim reached = new ManualResetEventSlim(false)) + using (ManualResetEventSlim block = new ManualResetEventSlim(false)) + using (CancellationTokenSource cts = new CancellationTokenSource()) + { + gitProcess.InvokeReachedBlock = reached; + gitProcess.BlockInvokeUntilSignaled = block; + + Exception caught = null; + Thread worker = new Thread(() => + { + try + { + dut.TryGetCredentials(tracer, out _, out _, GitAuthentication.BackgroundCredentialTimeoutMs, cts.Token); + } + catch (Exception e) + { + caught = e; + } + }) + { + IsBackground = true, + }; + worker.Start(); + + reached.Wait(TimeSpan.FromSeconds(5)).ShouldBeTrue(); + cts.Cancel(); + worker.Join(TimeSpan.FromMilliseconds(100)).ShouldBeFalse(); + block.Set(); + worker.Join(TimeSpan.FromSeconds(5)).ShouldBeTrue(); + caught.ShouldBeNull(); + gitProcess.LastInvokedCancellationToken.CanBeCanceled.ShouldBeFalse(); + } + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void CancellationInterruptsAuthenticationLockWaitBeforeHelperOwnership() + { + MockTracer tracer = new MockTracer(); + MockGitProcess gitProcess = this.GetGitProcess(); + GitAuthentication dut = new GitAuthentication(gitProcess, "mock://repoUrl"); + dut.TryInitializeAndRequireAuth(tracer, out _); + dut.TryGetCredentials(tracer, out string authString, out _).ShouldBeTrue(); + dut.RejectCredentials(tracer, authString); + + using (ManualResetEventSlim reached = new ManualResetEventSlim(false)) + using (ManualResetEventSlim block = new ManualResetEventSlim(false)) + using (CancellationTokenSource cts = new CancellationTokenSource()) + { + gitProcess.InvokeReachedBlock = reached; + gitProcess.BlockInvokeUntilSignaled = block; + + Exception firstError = null; + Thread first = new Thread(() => + { + try + { + dut.TryGetCredentials(tracer, out _, out _, GitAuthentication.BackgroundCredentialTimeoutMs); + } + catch (Exception e) + { + firstError = e; + } + }) + { + IsBackground = true, + }; + first.Start(); + + reached.Wait(TimeSpan.FromSeconds(5)).ShouldBeTrue(); + cts.Cancel(); + Assert.Throws( + () => dut.TryGetCredentials(tracer, out _, out _, cancellationToken: cts.Token)); + + block.Set(); + first.Join(TimeSpan.FromSeconds(5)).ShouldBeTrue(); + firstError.ShouldBeNull(); + } + } + + [TestCase] + public void CredentialGateTimeoutDoesNotStartConcurrentHelper() + { + MockTracer tracer = new MockTracer(); + MockGitProcess gitProcess = this.GetGitProcess(); + GitAuthentication dut = new GitAuthentication(gitProcess, "mock://repoUrl") + { + CredentialGateWaitTimeoutMs = 20, + }; + + using (ManualResetEventSlim reached = new ManualResetEventSlim(false)) + using (ManualResetEventSlim block = new ManualResetEventSlim(false)) + { + gitProcess.InvokeReachedBlock = reached; + gitProcess.BlockInvokeUntilSignaled = block; + + Thread first = new Thread(() => dut.TryInitializeAndRequireAuth(tracer, out _, credentialTimeoutMs: 20)) + { + IsBackground = true, + }; + first.Start(); + + reached.Wait(TimeSpan.FromSeconds(5)).ShouldBeTrue(); + int commandCount = gitProcess.CommandsRun.Count; + + dut.TryInitializeAndRequireAuth(tracer, out string error, credentialTimeoutMs: 20).ShouldBeFalse(); + error.ShouldContain("another credential operation"); + gitProcess.CommandsRun.Count.ShouldEqual(commandCount); + + gitProcess.BlockInvokeUntilSignaled = null; + block.Set(); + first.Join(TimeSpan.FromSeconds(5)).ShouldBeTrue(); + } + } + + [TestCase] + public void ActiveCredentialReloadIgnoresPerRequestCancellation() + { + MockTracer tracer = new MockTracer(); + MockGitProcess gitProcess = this.GetGitProcess(); + GitAuthentication dut = new GitAuthentication(gitProcess, "mock://repoUrl"); + dut.TryInitializeAndRequireAuth(tracer, out _); + dut.TryGetCredentials(tracer, out string authString, out _).ShouldBeTrue(); + + using (ManualResetEventSlim reached = new ManualResetEventSlim(false)) + using (ManualResetEventSlim block = new ManualResetEventSlim(false)) + using (CancellationTokenSource cts = new CancellationTokenSource()) + { + gitProcess.InvokeReachedBlock = reached; + gitProcess.BlockInvokeUntilSignaled = block; + + Exception caught = null; + Thread worker = new Thread(() => + { + try + { + dut.RejectCredentials(tracer, authString, GitAuthentication.BackgroundCredentialTimeoutMs, cts.Token); + } + catch (Exception e) + { + caught = e; + } + }) + { + IsBackground = true, + }; + worker.Start(); + + reached.Wait(TimeSpan.FromSeconds(5)).ShouldBeTrue(); + cts.Cancel(); + worker.Join(TimeSpan.FromMilliseconds(100)).ShouldBeFalse(); + block.Set(); + worker.Join(TimeSpan.FromSeconds(5)).ShouldBeTrue(); + caught.ShouldBeNull(); + gitProcess.LastInvokedCancellationToken.CanBeCanceled.ShouldBeFalse(); + } + } + private MockGitProcess GetGitProcess() { MockGitProcess gitProcess = new MockGitProcess(); diff --git a/GVFS/GVFS.UnitTests/Git/GitProcessTests.cs b/GVFS/GVFS.UnitTests/Git/GitProcessTests.cs index 96777c700..d267f695c 100644 --- a/GVFS/GVFS.UnitTests/Git/GitProcessTests.cs +++ b/GVFS/GVFS.UnitTests/Git/GitProcessTests.cs @@ -1,18 +1,114 @@ using GVFS.Common.Git; using GVFS.Tests.Should; +using GVFS.UnitTests.Category; using GVFS.UnitTests.Mock.Common; using GVFS.UnitTests.Mock.Git; using NUnit.Framework; +using System; using System.Collections.Generic; using System.Diagnostics; using System.IO; using System.Text; +using System.Threading; namespace GVFS.UnitTests.Git { [TestFixture] public class GitProcessTests { + [TestCase] + public void WaitForOutputDrainStopsAtTimeout() + { + using (ManualResetEventSlim outputCompleted = new ManualResetEventSlim(false)) + using (ManualResetEventSlim errorCompleted = new ManualResetEventSlim(false)) + { + Stopwatch stopwatch = Stopwatch.StartNew(); + + GitProcess.WaitForOutputDrain( + outputCompleted, + errorCompleted, + timeoutMs: 20, + CancellationToken.None, + out bool cancellationRequested) + .ShouldBeFalse("Output drain must not wait indefinitely for inherited handles to close"); + + cancellationRequested.ShouldBeFalse(); + stopwatch.Elapsed.ShouldBeAtLeast(TimeSpan.FromMilliseconds(10)); + } + } + + [TestCase] + public void WaitForOutputDrainObservesCancellation() + { + using (ManualResetEventSlim outputCompleted = new ManualResetEventSlim(false)) + using (ManualResetEventSlim errorCompleted = new ManualResetEventSlim(false)) + using (CancellationTokenSource cts = new CancellationTokenSource()) + { + cts.Cancel(); + + GitProcess.WaitForOutputDrain( + outputCompleted, + errorCompleted, + timeoutMs: 30_000, + cts.Token, + out bool cancellationRequested) + .ShouldBeFalse(); + + cancellationRequested.ShouldBeTrue(); + } + } + + [TestCase] + public void WaitForOutputDrainSucceedsAfterBothStreamsClose() + { + using (ManualResetEventSlim outputCompleted = new ManualResetEventSlim(true)) + using (ManualResetEventSlim errorCompleted = new ManualResetEventSlim(true)) + { + GitProcess.WaitForOutputDrain( + outputCompleted, + errorCompleted, + timeoutMs: 20, + CancellationToken.None, + out bool cancellationRequested) + .ShouldBeTrue(); + + cancellationRequested.ShouldBeFalse(); + } + } + + [TestCase] + public void InvokeGitImplMarksRealProcessTimeout() + { + TestGitProcess gitProcess = new TestGitProcess(); + Stopwatch stopwatch = Stopwatch.StartNew(); + + GitProcess.Result result = gitProcess.RunCommand( + "/d /c \"ping 127.0.0.1 -n 6 > nul\"", + timeoutMs: 100, + CancellationToken.None); + + result.TimedOut.ShouldBeTrue(); + result.ExitCodeIsFailure.ShouldBeTrue(); + stopwatch.Elapsed.ShouldBeAtMost(TimeSpan.FromSeconds(15)); + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void InvokeGitImplCancelsRealProcessWait() + { + TestGitProcess gitProcess = new TestGitProcess(); + using (CancellationTokenSource cts = new CancellationTokenSource()) + { + cts.CancelAfter(100); + + Assert.Throws( + () => gitProcess.RunCommand( + "/d /c \"ping 127.0.0.1 -n 6 > nul\"", + timeoutMs: 30_000, + cts.Token)); + } + } + [TestCase] public void ReadStdOutTokens_SplitsOnNul() { @@ -658,5 +754,27 @@ public void QuoteGitPath_RoundTripThroughProcess() } } } + + private class TestGitProcess : GitProcess + { + public TestGitProcess() + : base(Environment.GetEnvironmentVariable("ComSpec"), Path.GetTempPath()) + { + } + + public Result RunCommand(string command, int timeoutMs, CancellationToken cancellationToken) + { + return this.InvokeGitImpl( + command, + workingDirectory: null, + dotGitDirectory: null, + useReadObjectHook: false, + writeStdIn: null, + parseStdOutLine: null, + timeoutMs: timeoutMs, + usePreCommandHook: false, + cancellationToken: cancellationToken); + } + } } } diff --git a/GVFS/GVFS.UnitTests/Http/GitObjectsHttpRequestorTests.cs b/GVFS/GVFS.UnitTests/Http/GitObjectsHttpRequestorTests.cs index 1e7236202..1b1e6320f 100644 --- a/GVFS/GVFS.UnitTests/Http/GitObjectsHttpRequestorTests.cs +++ b/GVFS/GVFS.UnitTests/Http/GitObjectsHttpRequestorTests.cs @@ -344,6 +344,21 @@ public void SizesRequestFallsBackThroughGlobalCacheServerToOrigin() RetryCircuitBreaker.ConsecutiveFailures.ShouldEqual(0); } + [TestCase] + public void SizesCredentialTimeoutDoesNotRetryOrFallBack() + { + TestGitObjectsHttpRequestor requestor = this.CreateRequestor(maxRetries: 3); + requestor.EnqueueResponse( + HttpStatusCode.Unauthorized, + shouldRetry: false, + credentialOperationTimedOut: true); + + requestor.QueryForFileSizes(new[] { "0123456789abcdef" }, CancellationToken.None); + + requestor.RequestUris.Count.ShouldEqual(1); + requestor.RequestUris[0].AbsoluteUri.ShouldEqual(EndpointCacheServerUrl + "/gvfs/sizes"); + } + [TestCase] public void SizesHttpFallbackDoesNotChargeCircuitBreaker() { @@ -434,9 +449,10 @@ public void EnqueueResponse( HttpStatusCode statusCode, string body = "", bool shouldRetry = false, - bool shouldRecordFailure = true) + bool shouldRecordFailure = true, + bool credentialOperationTimedOut = false) { - this.responses.Enqueue(Tuple.Create(statusCode, body, shouldRetry, shouldRecordFailure)); + this.responses.Enqueue(Tuple.Create(statusCode, body, shouldRetry, shouldRecordFailure, credentialOperationTimedOut)); } public void EnqueueException(Exception exception) @@ -474,7 +490,7 @@ protected override GitEndPointResponseData SendProtocolRequest( onResponseDisposed: null); } - Tuple response = (Tuple)nextResponse; + Tuple response = (Tuple)nextResponse; if (response.Item1 == HttpStatusCode.OK) { @@ -492,7 +508,8 @@ protected override GitEndPointResponseData SendProtocolRequest( shouldRetry: response.Item3, message: null, onResponseDisposed: null, - shouldRecordFailure: response.Item4); + shouldRecordFailure: response.Item4, + credentialFetchTimedOut: response.Item5); } } diff --git a/GVFS/GVFS.UnitTests/Http/HttpRequestorTests.cs b/GVFS/GVFS.UnitTests/Http/HttpRequestorTests.cs index e81b81170..9c648ab1d 100644 --- a/GVFS/GVFS.UnitTests/Http/HttpRequestorTests.cs +++ b/GVFS/GVFS.UnitTests/Http/HttpRequestorTests.cs @@ -1,8 +1,16 @@ +using GVFS.Common; +using GVFS.Common.Git; using GVFS.Common.Http; +using GVFS.Common.Tracing; using GVFS.Tests.Should; +using GVFS.UnitTests.Mock.Common; +using GVFS.UnitTests.Mock.Git; using NUnit.Framework; using System; using System.Net; +using System.Net.Http; +using System.Threading; +using System.Threading.Tasks; namespace GVFS.UnitTests.Http { @@ -84,5 +92,230 @@ public void AuthorityForTelemetryExcludesCredentialsAndRequestPath() HttpRequestor.GetAuthorityForTelemetry(uri).ShouldEqual("cache.example.com:8443"); } + + private const string RepoUrl = "mock://repoUrl"; + private const string AzureDevOpsUseHttpPathString = "-c credential.\"https://dev.azure.com\".useHttpPath=true"; + + [TestCase] + public void SendRequestReleasesConnectionBeforeCredentialReject() + { + this.RunConnectionReleaseTest(); + } + + [TestCase] + public void SendRequestDoesNotDoubleReleaseConnectionWhenCancellationWaitsForActiveReject() + { + MockTracer tracer = new MockTracer(); + MockGitProcess gitProcess = CreateGitProcess(); + GitAuthentication authentication = CreateInitializedAuthentication(tracer, gitProcess); + MockGVFSEnlistment enlistment = new MockGVFSEnlistment(gitProcess, authentication); + + using (ManualResetEventSlim reached = new ManualResetEventSlim(false)) + using (ManualResetEventSlim block = new ManualResetEventSlim(false)) + using (CancellationTokenSource cts = new CancellationTokenSource()) + using (StubHttpMessageHandler handler = new StubHttpMessageHandler(HttpStatusCode.Unauthorized, "unauthorized")) + using (TestingHttpRequestor requestor = new TestingHttpRequestor(tracer, new RetryConfig(), enlistment, handler)) + { + int before = HttpRequestor.AvailableConnectionCount; + gitProcess.InvokeReachedBlock = reached; + gitProcess.BlockInvokeUntilSignaled = block; + + Exception caught = null; + Thread worker = new Thread(() => + { + try + { + using (requestor.Send(cts.Token)) + { + } + } + catch (Exception e) + { + caught = e; + } + }); + worker.IsBackground = true; + worker.Start(); + + reached.Wait(TimeSpan.FromSeconds(5)).ShouldEqual(true, "The reject leg should have started a git invocation"); + HttpRequestor.AvailableConnectionCount.ShouldEqual(before, "The connection slot should have been released before the reject leg ran"); + + cts.Cancel(); + worker.Join(TimeSpan.FromMilliseconds(100)).ShouldBeFalse( + "Cancellation must not terminate an active shared credential helper"); + block.Set(); + worker.Join(TimeSpan.FromSeconds(5)).ShouldBeTrue( + "The request should finish after the active credential helper returns"); + + caught.ShouldBeNull("Cancellation must not abort an active credential rejection"); + + // The key invariant: the early release plus the canceled reject must not + // double-release the process-wide connection permit. + HttpRequestor.AvailableConnectionCount.ShouldEqual(before, "The connection slot must be released exactly once, not double-released"); + } + } + + [TestCase] + public void CredentialTimeoutDoesNotFallBackToGlobalEndpoint() + { + using (GitEndPointResponseData response = new GitEndPointResponseData( + HttpStatusCode.Unauthorized, + new GitObjectsHttpException(HttpStatusCode.Unauthorized, "credential timeout"), + shouldRetry: false, + message: null, + onResponseDisposed: null, + credentialFetchTimedOut: true)) + { + GitObjectsHttpRequestor.ShouldFallBackToGlobalEndpoint( + hasFallbackEndPoint: true, + useFallbackEndPoint: false, + response) + .ShouldBeFalse("A second endpoint uses the same timed-out credential provider"); + } + } + + [TestCase] + public void CredentialRejectTimeoutStopsCurrentRequestRetries() + { + MockTracer tracer = new MockTracer(); + MockGitProcess gitProcess = CreateGitProcess(); + GitAuthentication authentication = CreateInitializedAuthentication(tracer, gitProcess); + MockGVFSEnlistment enlistment = new MockGVFSEnlistment(gitProcess, authentication); + + gitProcess.SetExpectedCommandResult( + $"{AzureDevOpsUseHttpPathString} credential fill", + () => new GitProcess.Result(string.Empty, "Operation timed out: git credential fill", GitProcess.Result.GenericFailureCode, false, false, timedOut: true), + matchPrefix: true); + + using (StubHttpMessageHandler handler = new StubHttpMessageHandler(HttpStatusCode.Unauthorized, "unauthorized")) + using (TestingHttpRequestor requestor = new TestingHttpRequestor(tracer, new RetryConfig(), enlistment, handler)) + using (GitEndPointResponseData response = requestor.Send(CancellationToken.None)) + { + response.ShouldRetry.ShouldBeFalse("The current request must stop after credential rejection times out"); + response.CredentialFetchTimedOut.ShouldBeTrue("Endpoint fallback must see the terminal credential timeout"); + } + } + + private static MockGitProcess CreateGitProcess() + { + MockGitProcess gitProcess = new MockGitProcess(); + gitProcess.SetExpectedCommandResult("config gvfs.FunctionalTests.UserName", () => new GitProcess.Result(string.Empty, string.Empty, GitProcess.Result.GenericFailureCode)); + gitProcess.SetExpectedCommandResult("config gvfs.FunctionalTests.Password", () => new GitProcess.Result(string.Empty, string.Empty, GitProcess.Result.GenericFailureCode)); + gitProcess.SetExpectedCommandResult("config --get-urlmatch http mock://repoUrl", () => new GitProcess.Result(string.Empty, string.Empty, GitProcess.Result.SuccessCode)); + + // HttpRequestor reads the connection limit on the first instance. + gitProcess.SetExpectedCommandResult("config gvfs.max-http-connections", () => new GitProcess.Result(string.Empty, string.Empty, GitProcess.Result.SuccessCode)); + + int rejections = 0; + gitProcess.SetExpectedCommandResult( + $"{AzureDevOpsUseHttpPathString} credential fill", + () => new GitProcess.Result("username=username\r\npassword=password" + rejections + "\r\n", string.Empty, GitProcess.Result.SuccessCode)); + + gitProcess.SetExpectedCommandResult( + $"{AzureDevOpsUseHttpPathString} credential approve", + () => new GitProcess.Result(string.Empty, string.Empty, GitProcess.Result.SuccessCode)); + + gitProcess.SetExpectedCommandResult( + $"{AzureDevOpsUseHttpPathString} credential reject", + () => + { + rejections++; + return new GitProcess.Result(string.Empty, string.Empty, GitProcess.Result.SuccessCode); + }); + + return gitProcess; + } + + private static GitAuthentication CreateInitializedAuthentication(MockTracer tracer, MockGitProcess gitProcess) + { + GitAuthentication authentication = new GitAuthentication(gitProcess, RepoUrl); + authentication.TryInitializeAndRequireAuth(tracer, out _); + + // Populate the credential cache so SendRequest attaches auth and reaches the reject leg. + authentication.TryGetCredentials(tracer, out _, out _).ShouldBeTrue(); + + // Force the non-anonymous path; production determines this by probing the server. + authentication.SetIsAnonymousForTesting(false); + + return authentication; + } + + private void RunConnectionReleaseTest() + { + MockTracer tracer = new MockTracer(); + MockGitProcess gitProcess = CreateGitProcess(); + GitAuthentication authentication = CreateInitializedAuthentication(tracer, gitProcess); + MockGVFSEnlistment enlistment = new MockGVFSEnlistment(gitProcess, authentication); + + using (ManualResetEventSlim reached = new ManualResetEventSlim(false)) + using (ManualResetEventSlim block = new ManualResetEventSlim(false)) + using (StubHttpMessageHandler handler = new StubHttpMessageHandler(HttpStatusCode.Unauthorized, "unauthorized")) + using (TestingHttpRequestor requestor = new TestingHttpRequestor(tracer, new RetryConfig(), enlistment, handler)) + { + int before = HttpRequestor.AvailableConnectionCount; + gitProcess.InvokeReachedBlock = reached; + gitProcess.BlockInvokeUntilSignaled = block; + + GitEndPointResponseData response = null; + Thread worker = new Thread(() => response = requestor.Send(CancellationToken.None)); + worker.IsBackground = true; + worker.Start(); + + reached.Wait(TimeSpan.FromSeconds(5)).ShouldEqual(true, "The reject leg should have started a git invocation"); + + HttpRequestor.AvailableConnectionCount.ShouldEqual(before, "The connection slot should be released before the reject leg runs"); + + block.Set(); + worker.Join(TimeSpan.FromSeconds(5)).ShouldEqual(true, "The request should complete after the reject leg unblocks"); + + response.ShouldNotBeNull("Expected a response"); + response.HasErrors.ShouldEqual(true, "Expected a 401 error response"); + response.Dispose(); + + HttpRequestor.AvailableConnectionCount.ShouldEqual(before, "The connection slot should be fully released after completion"); + } + } + + private sealed class TestingHttpRequestor : HttpRequestor + { + public TestingHttpRequestor(ITracer tracer, RetryConfig retryConfig, Enlistment enlistment, HttpMessageHandler handler) + : base(tracer, retryConfig, enlistment, handler) + { + } + + protected override int CredentialTimeoutMs => GitAuthentication.BackgroundCredentialTimeoutMs; + + public GitEndPointResponseData Send(CancellationToken cancellationToken) + { + return this.SendRequest( + GetNewRequestId(), + new Uri("https://mock.gvfs/gvfs/objects"), + HttpMethod.Get, + requestContent: null, + cancellationToken: cancellationToken); + } + } + + private sealed class StubHttpMessageHandler : HttpMessageHandler + { + private readonly HttpStatusCode statusCode; + private readonly string body; + + public StubHttpMessageHandler(HttpStatusCode statusCode, string body) + { + this.statusCode = statusCode; + this.body = body; + } + + protected override Task SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) + { + HttpResponseMessage response = new HttpResponseMessage(this.statusCode) + { + Content = new StringContent(this.body), + }; + + return Task.FromResult(response); + } + } } } diff --git a/GVFS/GVFS.UnitTests/Mock/Common/MockGVFSEnlistment.cs b/GVFS/GVFS.UnitTests/Mock/Common/MockGVFSEnlistment.cs index 6fb128930..ab5d5dafe 100644 --- a/GVFS/GVFS.UnitTests/Mock/Common/MockGVFSEnlistment.cs +++ b/GVFS/GVFS.UnitTests/Mock/Common/MockGVFSEnlistment.cs @@ -34,6 +34,15 @@ public MockGVFSEnlistment(MockGitProcess gitProcess) this.gitProcess = gitProcess; } + public MockGVFSEnlistment(MockGitProcess gitProcess, GitAuthentication authentication) + : base(Path.Combine("mock:", "path"), "mock://repoUrl", Path.Combine("mock:", "git"), authentication) + { + this.gitProcess = gitProcess; + this.GitObjectsRoot = Path.Combine("mock:", "path", ".git", "objects"); + this.LocalObjectsRoot = this.GitObjectsRoot; + this.GitPackRoot = Path.Combine("mock:", "path", ".git", "objects", "pack"); + } + public override string GitObjectsRoot { get; protected set; } public override string LocalObjectsRoot { get; protected set; } diff --git a/GVFS/GVFS.UnitTests/Mock/Git/MockGitProcess.cs b/GVFS/GVFS.UnitTests/Mock/Git/MockGitProcess.cs index 6200cc2be..c7e4c2d82 100644 --- a/GVFS/GVFS.UnitTests/Mock/Git/MockGitProcess.cs +++ b/GVFS/GVFS.UnitTests/Mock/Git/MockGitProcess.cs @@ -8,6 +8,7 @@ using System.IO; using System.Linq; using System.Text; +using System.Threading; namespace GVFS.UnitTests.Mock.Git { @@ -39,6 +40,24 @@ public MockGitProcess(string gitBinPath, string workingDirectoryRoot) /// once with different flags. /// public List InvocationsRun { get; } = new List(); + + /// + /// The timeout passed to every InvokeGitImpl call, in order. Lets tests assert that a + /// caller actually plumbed a finite timeout rather than defaulting to -1 (infinite). + /// + public List InvokedTimeoutMs { get; } = new List(); + + /// + /// The timeout passed to the most recent InvokeGitImpl call, or null if none has run. + /// + public int? LastInvokedTimeoutMs { get; private set; } + + public CancellationToken LastInvokedCancellationToken { get; private set; } + + public ManualResetEventSlim BlockInvokeUntilSignaled { get; set; } + + public ManualResetEventSlim InvokeReachedBlock { get; set; } + public bool ShouldFail { get; set; } public Dictionary StoredCredentials { get; } = new Dictionary(StringComparer.OrdinalIgnoreCase); public Dictionary> CredentialApprovals { get; } = new Dictionary>(); @@ -73,7 +92,7 @@ public void SetExpectedCommandResult(string command, Func result, bool m this.expectedCommandInfos.Add(commandInfo); } - public override bool TryStoreCredential(ITracer tracer, string repoUrl, string username, string password, out string error) + public override bool TryStoreCredential(ITracer tracer, string repoUrl, string username, string password, out string error, out bool timedOut, int timeoutMs = -1, CancellationToken cancellationToken = default) { Credential credential = new Credential(username, password); @@ -90,10 +109,10 @@ public override bool TryStoreCredential(ITracer tracer, string repoUrl, string u // Store the credential this.StoredCredentials[repoUrl] = credential; - return base.TryStoreCredential(tracer, repoUrl, username, password, out error); + return base.TryStoreCredential(tracer, repoUrl, username, password, out error, out timedOut, timeoutMs, cancellationToken); } - public override bool TryDeleteCredential(ITracer tracer, string repoUrl, string username, string password, out string error) + public override bool TryDeleteCredential(ITracer tracer, string repoUrl, string username, string password, out string error, out bool timedOut, int timeoutMs = -1, CancellationToken cancellationToken = default) { Credential credential = new Credential(username, password); @@ -110,7 +129,7 @@ public override bool TryDeleteCredential(ITracer tracer, string repoUrl, string // Erase the credential this.StoredCredentials.Remove(repoUrl); - return base.TryDeleteCredential(tracer, repoUrl, username, password, out error); + return base.TryDeleteCredential(tracer, repoUrl, username, password, out error, out timedOut, timeoutMs, cancellationToken); } protected override Result InvokeGitImpl( @@ -125,11 +144,22 @@ protected override Result InvokeGitImpl( bool usePrecommandHook = true, Action parseStdOutToken = null, bool mayRequireAuth = false, - bool? hasVisibleConsoleWindow = null) + bool? hasVisibleConsoleWindow = null, + CancellationToken cancellationToken = default) { this.CommandsRun.Add(command); this.DotGitDirectoriesUsed.Add(dotGitDirectory); this.InvocationsRun.Add(new GitInvocation(command, dotGitDirectory, mayRequireAuth, hasVisibleConsoleWindow)); + this.LastInvokedTimeoutMs = timeoutMs; + this.InvokedTimeoutMs.Add(timeoutMs); + this.LastInvokedCancellationToken = cancellationToken; + + ManualResetEventSlim blockUntilSignaled = this.BlockInvokeUntilSignaled; + if (blockUntilSignaled != null) + { + this.InvokeReachedBlock?.Set(); + blockUntilSignaled.Wait(cancellationToken); + } if (this.ShouldFail) {