From faa01d3b983def7998b804f28e1bf88fcb1c90f2 Mon Sep 17 00:00:00 2001 From: Tyrie Vella Date: Wed, 8 Jul 2026 10:49:44 -0700 Subject: [PATCH 1/2] Bound runtime credential fetch so prefetch can't hang on auth The runtime credential path (HttpRequestor.SendRequest -> GitAuthentication.TryGetCredentials/RejectCredentials -> TryCallGitCredential) called git-credential with timeoutMs = -1, so Process.WaitForExit(-1) waited forever. When a GCM auth popup was missed (e.g. behind another window), the mount's background maintenance PrefetchStep blocked indefinitely while holding the shared prefetch-commits-trees.lock, which in turn blocked a user-initiated `gvfs prefetch`. The mount startup auth path was already bounded via credentialTimeoutMs; this extends the same bound to every runtime credential invocation: - TryGetCredentials takes credentialTimeoutMs (default DefaultCredentialTimeoutMs) and plumbs it to TryCallGitCredential. - RejectCredentials, which reloads the credential on the 401-retry leg, takes and plumbs the same timeout (this leg is the actual stale-token hang path and was otherwise still unbounded). - ApproveCredentials, RejectCredentials and the ICredentialStore store/delete operations are bounded too. `git credential approve` and `git credential reject` previously ran with timeoutMs = -1 while holding gitAuthLock, so a stalled helper could still pin the prefetch lock forever even after the fill leg was bounded. - HttpRequestor exposes a protected virtual CredentialTimeoutMs and passes it to TryGetCredentials, RejectCredentials and ApproveCredentials. The bound is generous (120s) rather than the 30s default: 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 legitimately take longer than 30s to answer a GCM cold-start / MFA / smartcard prompt. 120s still bounds the hang while being long enough not to cut off a prompt the user is actively answering. The value lives on RetryConfig, which is already loaded once from git config and already passed into the HttpRequestor constructor alongside MaxRetries and Timeout. It is overridable via gvfs.credential-timeout-seconds; 0 or less restores the old unbounded wait as a field escape hatch. Loading it through RetryConfig keeps timeout parsing with the existing retry settings and avoids a config read for each request. The credential serialization gate now waits at least as long as the fetch it is serializing. It previously waited a fixed 60s, and on expiry fell through and spawned a second credential fetch. With a 120s fetch bound that guaranteed a second, competing GCM prompt in exactly the slow-prompt case the longer bound exists to tolerate. A timed-out fetch no longer asks the caller to retry. SendRequest previously returned shouldRetry: true for every credential failure, so a timeout burned the whole RetryWrapper budget (up to MaxAttempts x 120s), re-prompting the user each time. TryGetCredentials now reports whether the failure was a timeout, and SendRequest sets shouldRetry accordingly; genuine auth failures still retry as before. On timeout the git process tree is killed, not just git.exe. Killing only git.exe left the credential helper child alive, holding the credential store and showing orphaned prompt UI. The kill is now followed by a bounded wait so the async stdout/stderr readers flush before their buffers are read. The timeout is reported as a distinct CredentialFetchTimedOut telemetry event with structured timeoutMs and RepoAuthority fields, rather than only as warning message text. This is what makes the 120s choice measurable in the field: how often the bound fires, and whether a timeout is followed by a successful fetch (a prompt that was cut off) or not (a hang that was prevented). On timeout the fetch fails, backoff engages, the download gives up, and the lock is released instead of hanging forever. Tests: MockGitProcess now records the timeout passed to each git invocation, so tests can assert the bound is actually plumbed rather than just that a failure message appears. The timeout test asserts the observed timeout and the rendered "within 1 seconds" message; reverting the plumbing makes it fail (verified by mutation). Adds a test that the 401-reject leg bounds both the credential reload and the erase, a test that only genuine timeouts are reported as timeouts so a real auth failure still retries (also mutation-verified), and RetryConfig coverage for the default, configured, and unbounded-escape-hatch values. Assisted-by: Claude Opus 4.8 Signed-off-by: Tyrie Vella --- GVFS/GVFS.Common/GVFSConstants.cs | 7 ++ GVFS/GVFS.Common/Git/GitAuthentication.cs | 65 ++++++++++++----- GVFS/GVFS.Common/Git/GitProcess.cs | 55 +++++++++++--- GVFS/GVFS.Common/Git/ICredentialStore.cs | 6 +- GVFS/GVFS.Common/Http/HttpRequestor.cs | 24 +++++-- GVFS/GVFS.Common/RetryConfig.cs | 71 ++++++++++++++++++- .../GVFS.UnitTests/Common/RetryConfigTests.cs | 33 +++++++++ .../GVFS.UnitTests/Mock/Git/MockGitProcess.cs | 21 ++++-- 8 files changed, 244 insertions(+), 38 deletions(-) diff --git a/GVFS/GVFS.Common/GVFSConstants.cs b/GVFS/GVFS.Common/GVFSConstants.cs index 5cf22eabe2..43df3850e4 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 a runtime credential fetch may block waiting on the + /// credential manager, in seconds. 0 or negative restores the pre-bound + /// behavior of waiting indefinitely. Read once into . + /// + public const string CredentialTimeoutSeconds = GVFSPrefix + "credential-timeout-seconds"; + public const string PrefetchUseIdx = GVFSPrefix + "prefetch-use-idx"; public const bool PrefetchUseIdxDefault = false; diff --git a/GVFS/GVFS.Common/Git/GitAuthentication.cs b/GVFS/GVFS.Common/Git/GitAuthentication.cs index 5f9db0c724..b719819b0a 100644 --- a/GVFS/GVFS.Common/Git/GitAuthentication.cs +++ b/GVFS/GVFS.Common/Git/GitAuthentication.cs @@ -23,6 +23,13 @@ private enum AuthenticationState public const int DefaultCredentialTimeoutMs = 30_000; public const int BackgroundCredentialTimeoutMs = 120_000; + /// + /// 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 + /// itself, so a slow but legitimate prompt cannot cause a second prompt. + /// + private const int DefaultCredentialGateWaitMs = 60_000; + private readonly Lock gitAuthLock = new Lock(); private readonly SemaphoreSlim credentialGate = new SemaphoreSlim(1, 1); private readonly ICredentialStore credentialStore; @@ -116,7 +123,7 @@ internal void MarkInitializationStarted() private GitSsl GitSsl { get; } - public void ApproveCredentials(ITracer tracer, string credentialString) + public void ApproveCredentials(ITracer tracer, string credentialString, int credentialTimeoutMs = DefaultCredentialTimeoutMs) { lock (this.gitAuthLock) { @@ -134,7 +141,7 @@ 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.credentialStore.TryStoreCredential(tracer, this.repoUrl, username, password, out string error, credentialTimeoutMs)) { // Storing credentials is best effort attempt - log failure, but do not fail tracer.RelatedWarning("Failed to store credential string: {0}", error); @@ -155,7 +162,7 @@ public void ApproveCredentials(ITracer tracer, string credentialString) } } - public void RejectCredentials(ITracer tracer, string credentialString) + public void RejectCredentials(ITracer tracer, string credentialString, int credentialTimeoutMs = DefaultCredentialTimeoutMs) { lock (this.gitAuthLock) { @@ -166,7 +173,7 @@ 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)) + if (this.TryCallGitCredential(tracer, out string getCredentialError, out _, credentialTimeoutMs)) { if (this.cachedCredentialString != cachedCredentialAtStartOfReject) { @@ -187,7 +194,7 @@ 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)) + if (!this.credentialStore.TryDeleteCredential(tracer, this.repoUrl, username, password, out string error, credentialTimeoutMs)) { // Deleting credentials is best effort attempt - log failure, but do not fail tracer.RelatedWarning("Failed to delete credential string: {0}", error); @@ -202,7 +209,7 @@ 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); + this.credentialStore.TryDeleteCredential(tracer, this.repoUrl, username: null, password: null, error: out string error, timeoutMs: credentialTimeoutMs); } this.cachedCredentialString = null; @@ -230,8 +237,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) { + return this.TryGetCredentials(tracer, out credentialString, out errorMessage, out _, credentialTimeoutMs); + } + + /// + /// 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) + { + timedOut = false; + if (!this.isInitialized) { // Initialization may still be running in the background (mount can @@ -267,7 +286,7 @@ public bool TryGetCredentials(ITracer tracer, out string credentialString, out s return false; } - if (!this.TryCallGitCredential(tracer, out errorMessage)) + if (!this.TryCallGitCredential(tracer, out errorMessage, out timedOut, credentialTimeoutMs)) { return false; } @@ -402,7 +421,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 @@ -444,12 +463,22 @@ internal bool TryInitializeAndRequireAuth(ITracer tracer, out string errorMessag throw new InvalidOperationException("Already initialized"); } + internal bool TryInitializeAndRequireAuth( + ITracer tracer, + out string errorMessage, + int credentialTimeoutMs = BackgroundCredentialTimeoutMs) + { + if (this.isInitialized) + { + throw new InvalidOperationException("Already initialized"); + } + this.MarkInitializationStarted(); this.MarkAuthenticationRequired(); try { - if (this.TryCallGitCredential(tracer, out errorMessage)) + if (this.TryCallGitCredential(tracer, out errorMessage, out _, credentialTimeoutMs)) { this.MarkInitialized(); return true; @@ -583,20 +612,24 @@ 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) { // 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); + // Wait at least as long as the fetch itself may take; otherwise the + // gate would expire while the in-flight fetch is still legitimately + // waiting on the user, and we would fall through and spawn a second + // competing GCM prompt in exactly the slow-prompt case this bound + // exists to tolerate. + int gateTimeoutMs = timeoutMs < 0 ? DefaultCredentialGateWaitMs : Math.Max(DefaultCredentialGateWaitMs, timeoutMs); + bool acquired = this.credentialGate.Wait(gateTimeoutMs); + timedOut = false; try { string gitUsername; string gitPassword; - if (!this.credentialStore.TryGetCredential(tracer, this.repoUrl, out gitUsername, out gitPassword, out errorMessage, timeoutMs)) + if (!this.credentialStore.TryGetCredential(tracer, this.repoUrl, out gitUsername, out gitPassword, out errorMessage, out timedOut, timeoutMs)) { this.UpdateBackoff(); return false; diff --git a/GVFS/GVFS.Common/Git/GitProcess.cs b/GVFS/GVFS.Common/Git/GitProcess.cs index d97e3af857..9dc3f7a8d6 100644 --- a/GVFS/GVFS.Common/Git/GitProcess.cs +++ b/GVFS/GVFS.Common/Git/GitProcess.cs @@ -51,6 +51,12 @@ 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 static readonly Encoding UTF8NoBOM = new UTF8Encoding(false); // Key names defined by the git credential protocol. They are names, not values, so they are @@ -280,7 +286,7 @@ 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, int timeoutMs = -1) { StringBuilder sb = new StringBuilder(); sb.AppendFormat("url={0}\n", repoUrl); @@ -301,7 +307,8 @@ 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); if (result.ExitCodeIsFailure) { @@ -315,7 +322,7 @@ 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, int timeoutMs = -1) { StringBuilder sb = new StringBuilder(); sb.AppendFormat("url={0}\n", repoUrl); @@ -328,7 +335,8 @@ 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); if (result.ExitCodeIsFailure) { @@ -418,11 +426,13 @@ public virtual bool TryGetCredential( out string username, out string password, out string errorMessage, + out bool timedOut, int timeoutMs = -1) { username = null; password = null; errorMessage = null; + timedOut = false; using (ITracer activity = tracer.StartActivity(nameof(this.TryGetCredential), EventLevel.Informational)) { @@ -456,10 +466,21 @@ public virtual bool TryGetCredential( if (gitCredentialOutput.Errors.StartsWith("Operation timed out")) { + 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); + errorData.Add("RepoUrl", repoUrl); + tracer.RelatedEvent( + EventLevel.Warning, + "CredentialFetchTimedOut", errorData, - "Git credential fill timed out after " + timeoutMs + "ms", Keywords.Network | Keywords.Telemetry); TraceCredentialFillErrorOutput(tracer, gitCredentialOutput.Errors); } @@ -1430,12 +1451,30 @@ protected virtual Result InvokeGitImpl( { this.executingProcess.BeginOutputReadLine(); - if (!this.executingProcess.WaitForExit(timeoutMs)) + 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 _); + } + } + + if (this.WaitForExitWithCancellation(ProcessKillTimeoutMs, out bool _)) + { + this.executingProcess.WaitForExit(); + } + + if (cancellationRequested) + { + throw new OperationCanceledException(cancellationToken); + } return new Result(output.ToString(), "Operation timed out: " + errors.ToString(), Result.GenericFailureCode, output.Truncated, errors.Truncated); } + + this.executingProcess.WaitForExit(); } } diff --git a/GVFS/GVFS.Common/Git/ICredentialStore.cs b/GVFS/GVFS.Common/Git/ICredentialStore.cs index 9ab38e13d9..1a578418ea 100644 --- a/GVFS/GVFS.Common/Git/ICredentialStore.cs +++ b/GVFS/GVFS.Common/Git/ICredentialStore.cs @@ -4,10 +4,10 @@ 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); - 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, int timeoutMs = -1); - 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, int timeoutMs = -1); } } diff --git a/GVFS/GVFS.Common/Http/HttpRequestor.cs b/GVFS/GVFS.Common/Http/HttpRequestor.cs index 4ea8e41d57..63fc0b0956 100644 --- a/GVFS/GVFS.Common/Http/HttpRequestor.cs +++ b/GVFS/GVFS.Common/Http/HttpRequestor.cs @@ -103,6 +103,17 @@ internal HttpRequestor( protected ITracer Tracer { get; } + // 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,12 +147,17 @@ 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)) { return new GitEndPointResponseData( HttpStatusCode.Unauthorized, new GitObjectsHttpException(HttpStatusCode.Unauthorized, errorMessage), - shouldRetry: true, + shouldRetry: !credentialFetchTimedOut, message: null, onResponseDisposed: null); } @@ -238,7 +254,7 @@ protected GitEndPointResponseData SendRequest( if (!sendAnonymous) { - this.authentication.ApproveCredentials(this.Tracer, authString); + this.authentication.ApproveCredentials(this.Tracer, authString, this.CredentialTimeoutMs); } else if (!forceAnonymous) { @@ -294,7 +310,7 @@ protected GitEndPointResponseData SendRequest( } else if (ShouldRejectCredentials(response.StatusCode, errorMessage)) { - this.authentication.RejectCredentials(this.Tracer, authString); + this.authentication.RejectCredentials(this.Tracer, authString, this.CredentialTimeoutMs); 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, response.StatusCode, errorMessage); diff --git a/GVFS/GVFS.Common/RetryConfig.cs b/GVFS/GVFS.Common/RetryConfig.cs index 4462a18bcc..c4e8b5ca27 100644 --- a/GVFS/GVFS.Common/RetryConfig.cs +++ b/GVFS/GVFS.Common/RetryConfig.cs @@ -11,6 +11,15 @@ 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; + private const string EtwArea = nameof(RetryConfig); private const int MinRetries = 0; @@ -23,9 +32,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 +51,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 +102,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,6 +132,7 @@ 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" } }); } @@ -99,8 +140,7 @@ public static bool TryLoadFromGitConfig(ITracer tracer, GitProcess git, out Retr return true; } - private static bool TryLoadMaxRetries(GitProcess git, out int attempts, out string error) - { + private static bool TryLoadMaxRetries(GitProcess git, out int attempts, out string error) { return TryGetFromGitConfig( git, GVFSConstants.GitConfig.MaxRetriesConfig, @@ -129,6 +169,31 @@ 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; + } + + 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.UnitTests/Common/RetryConfigTests.cs b/GVFS/GVFS.UnitTests/Common/RetryConfigTests.cs index 0f8c45b26d..c418ff74e7 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,33 @@ 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 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); } } } diff --git a/GVFS/GVFS.UnitTests/Mock/Git/MockGitProcess.cs b/GVFS/GVFS.UnitTests/Mock/Git/MockGitProcess.cs index 6200cc2be8..3272726519 100644 --- a/GVFS/GVFS.UnitTests/Mock/Git/MockGitProcess.cs +++ b/GVFS/GVFS.UnitTests/Mock/Git/MockGitProcess.cs @@ -39,6 +39,17 @@ 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; } + + /// + /// The timeout passed to the most recent InvokeGitImpl call, or null if none has run. + /// + public int? LastInvokedTimeoutMs { get; private set; } public bool ShouldFail { get; set; } public Dictionary StoredCredentials { get; } = new Dictionary(StringComparer.OrdinalIgnoreCase); public Dictionary> CredentialApprovals { get; } = new Dictionary>(); @@ -73,7 +84,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, int timeoutMs = -1) { Credential credential = new Credential(username, password); @@ -90,10 +101,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, timeoutMs); } - 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, int timeoutMs = -1) { Credential credential = new Credential(username, password); @@ -110,7 +121,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, timeoutMs); } protected override Result InvokeGitImpl( @@ -130,6 +141,8 @@ protected override Result InvokeGitImpl( this.CommandsRun.Add(command); this.DotGitDirectoriesUsed.Add(dotGitDirectory); this.InvocationsRun.Add(new GitInvocation(command, dotGitDirectory, mayRequireAuth, hasVisibleConsoleWindow)); + this.LastInvokedTimeoutMs = timeoutMs; + this.InvokedTimeoutMs.Add(timeoutMs); if (this.ShouldFail) { From 08ad1413861a2846088dc60f6c84ab759437e0b9 Mon Sep 17 00:00:00 2001 From: Tyrie Vella Date: Tue, 11 Aug 2026 09:09:06 -0700 Subject: [PATCH 2/2] Prevent authentication resource contention and bound credential operations Serialize credential helpers and preserve terminal timeout state across retries and endpoint fallback. Make waits cancelable before helper ownership. After ownership, use the configured deadline instead of request cancellation. Release HTTP capacity before credential rejection and prevent duplicate permit releases. Use typed timeout results. Bound process exit and output drain waits, and contain partial process-tree termination failures. Add regression tests for timeout, contention, cancellation, process cleanup, and retry suppression. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- GVFS/GVFS.Common/GVFSConstants.cs | 7 +- GVFS/GVFS.Common/Git/GVFSGitObjects.cs | 19 +- GVFS/GVFS.Common/Git/GitAuthentication.cs | 295 ++++++++++++++--- GVFS/GVFS.Common/Git/GitProcess.cs | 253 +++++++++++--- GVFS/GVFS.Common/Git/ICredentialStore.cs | 7 +- .../Http/GitEndPointResponseData.cs | 6 +- .../Http/GitObjectsHttpRequestor.cs | 27 +- GVFS/GVFS.Common/Http/HttpRequestor.cs | 78 ++++- GVFS/GVFS.Common/RetryConfig.cs | 17 +- GVFS/GVFS.Platform.Windows/WindowsPlatform.cs | 47 ++- .../Common/Git/GitProcessCredentialTests.cs | 42 ++- .../GVFS.UnitTests/Common/RetryConfigTests.cs | 28 ++ .../GVFS.UnitTests/Git/GVFSGitObjectsTests.cs | 43 ++- .../Git/GitAuthenticationTests.cs | 313 +++++++++++++++++- GVFS/GVFS.UnitTests/Git/GitProcessTests.cs | 118 +++++++ .../Http/GitObjectsHttpRequestorTests.cs | 25 +- .../GVFS.UnitTests/Http/HttpRequestorTests.cs | 233 +++++++++++++ .../Mock/Common/MockGVFSEnlistment.cs | 9 + .../GVFS.UnitTests/Mock/Git/MockGitProcess.cs | 29 +- 19 files changed, 1444 insertions(+), 152 deletions(-) diff --git a/GVFS/GVFS.Common/GVFSConstants.cs b/GVFS/GVFS.Common/GVFSConstants.cs index 43df3850e4..8ae80dd5a6 100644 --- a/GVFS/GVFS.Common/GVFSConstants.cs +++ b/GVFS/GVFS.Common/GVFSConstants.cs @@ -84,9 +84,9 @@ public static class GitConfig public const string MaxHttpConnectionsConfig = GVFSPrefix + "max-http-connections"; /// - /// Overrides how long a runtime credential fetch may block waiting on the - /// credential manager, in seconds. 0 or negative restores the pre-bound - /// behavior of waiting indefinitely. Read once into . + /// 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"; @@ -102,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 38065f28f0..d90fc65c4e 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 b719819b0a..145e1a5290 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,17 +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; /// /// 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 - /// itself, so a slow but legitimate prompt cannot cause a second prompt. + /// serialization. The effective wait is never shorter than the fetch timeout. /// private const int DefaultCredentialGateWaitMs = 60_000; - private readonly Lock gitAuthLock = new Lock(); + private readonly SemaphoreSlim gitAuthLock = new SemaphoreSlim(1, 1); private readonly SemaphoreSlim credentialGate = new SemaphoreSlim(1, 1); private readonly ICredentialStore credentialStore; private readonly string repoUrl; @@ -45,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; @@ -121,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, int credentialTimeoutMs = DefaultCredentialTimeoutMs) + /// + /// 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. @@ -141,10 +164,14 @@ public void ApproveCredentials(ITracer tracer, string credentialString, int cred string password; if (TryParseCredentialString(this.cachedCredentialString, out username, out password)) { - if (!this.credentialStore.TryStoreCredential(tracer, this.repoUrl, username, password, out string error, credentialTimeoutMs)) + 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; @@ -162,10 +189,11 @@ public void ApproveCredentials(ITracer tracer, string credentialString, int cred } } - public void RejectCredentials(ITracer tracer, string credentialString, int credentialTimeoutMs = DefaultCredentialTimeoutMs) + 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) @@ -173,18 +201,25 @@ public void RejectCredentials(ITracer tracer, string credentialString, int crede // 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, out _, credentialTimeoutMs)) + 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) @@ -194,10 +229,26 @@ public void RejectCredentials(ITracer tracer, string credentialString, int crede string password; if (TryParseCredentialString(this.cachedCredentialString, out username, out password)) { - if (!this.credentialStore.TryDeleteCredential(tracer, this.repoUrl, username, password, out string error, credentialTimeoutMs)) + 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 @@ -209,11 +260,26 @@ public void RejectCredentials(ITracer tracer, string credentialString, int crede ["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, timeoutMs: credentialTimeoutMs); + 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) @@ -221,6 +287,8 @@ public void RejectCredentials(ITracer tracer, string credentialString, int crede this.UpdateBackoff(); } } + + return false; } } @@ -237,9 +305,9 @@ public void RejectCredentials(ITracer tracer, string credentialString, int crede /// 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, int credentialTimeoutMs = DefaultCredentialTimeoutMs) + 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); + return this.TryGetCredentials(tracer, out credentialString, out errorMessage, out _, credentialTimeoutMs, cancellationToken); } /// @@ -247,7 +315,7 @@ public bool TryGetCredentials(ITracer tracer, out string credentialString, out s /// 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) + public bool TryGetCredentials(ITracer tracer, out string credentialString, out string errorMessage, out bool timedOut, int credentialTimeoutMs = DefaultCredentialTimeoutMs, CancellationToken cancellationToken = default) { timedOut = false; @@ -258,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"; @@ -276,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, out timedOut, credentialTimeoutMs)) + if (!this.TryCallGitCredential(tracer, out errorMessage, out timedOut, credentialTimeoutMs, cancellationToken)) { return false; } @@ -456,17 +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) - { - if (this.isInitialized) - { - throw new InvalidOperationException("Already initialized"); - } - - internal bool TryInitializeAndRequireAuth( - ITracer tracer, - out string errorMessage, - int credentialTimeoutMs = BackgroundCredentialTimeoutMs) + internal bool TryInitializeAndRequireAuth(ITracer tracer, out string errorMessage, int credentialTimeoutMs = Timeout.Infinite) { if (this.isInitialized) { @@ -598,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() @@ -612,32 +708,40 @@ private void MarkInitialized() this.initializationComplete.Set(); } - private bool TryCallGitCredential(ITracer tracer, out string errorMessage, out bool timedOut, 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 at least as long as the fetch itself may take; otherwise the - // gate would expire while the in-flight fetch is still legitimately - // waiting on the user, and we would fall through and spawn a second - // competing GCM prompt in exactly the slow-prompt case this bound - // exists to tolerate. - int gateTimeoutMs = timeoutMs < 0 ? DefaultCredentialGateWaitMs : Math.Max(DefaultCredentialGateWaitMs, timeoutMs); - bool acquired = this.credentialGate.Wait(gateTimeoutMs); + 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, out timedOut, 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 @@ -650,10 +754,95 @@ private bool TryCallGitCredential(ITracer tracer, out string errorMessage, out b } 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 9dc3f7a8d6..64e6235116 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; @@ -56,6 +52,7 @@ public class GitProcess : ICredentialStore /// 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); @@ -286,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, int timeoutMs = -1) + 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); @@ -308,10 +306,12 @@ public virtual bool TryDeleteCredential(ITracer tracer, string repoUrl, string u GenerateCredentialVerbCommand("reject"), stdin => stdin.Write(stdinConfig), usePreCommandHook: false, - timeoutMs: timeoutMs); + timeoutMs: timeoutMs, + cancellationToken: cancellationToken); if (result.ExitCodeIsFailure) { + timedOut = IsTimeoutResult(result); tracer.RelatedWarning("Git could not reject credentials: {0}", result.Errors); errorMessage = result.Errors; @@ -322,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, int timeoutMs = -1) + 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); @@ -336,10 +337,12 @@ public virtual bool TryStoreCredential(ITracer tracer, string repoUrl, string us GenerateCredentialVerbCommand("approve"), stdin => stdin.Write(stdinConfig), usePreCommandHook: false, - timeoutMs: timeoutMs); + timeoutMs: timeoutMs, + cancellationToken: cancellationToken); if (result.ExitCodeIsFailure) { + timedOut = IsTimeoutResult(result); tracer.RelatedWarning("Git could not approve credentials: {0}", result.Errors); errorMessage = result.Errors; @@ -350,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 @@ -420,6 +428,26 @@ public virtual bool TryGetCertificatePassword( } } + public virtual bool TryGetCredential( + ITracer tracer, + string repoUrl, + out string username, + out string password, + out string errorMessage, + 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, @@ -427,7 +455,8 @@ public virtual bool TryGetCredential( out string password, out string errorMessage, out bool timedOut, - int timeoutMs = -1) + int timeoutMs = -1, + CancellationToken cancellationToken = default) { username = null; password = null; @@ -452,7 +481,8 @@ public virtual bool TryGetCredential( usePreCommandHook: false, timeoutMs: timeoutMs, mayRequireAuth: true, - hasVisibleConsoleWindow: hasVisibleConsoleWindow); + hasVisibleConsoleWindow: hasVisibleConsoleWindow, + cancellationToken: cancellationToken); if (gitCredentialOutput.ExitCodeIsFailure) { @@ -464,7 +494,7 @@ 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"; @@ -476,13 +506,18 @@ public virtual bool TryGetCredential( errorData.Add("Area", nameof(GitProcess)); errorData.Add("Method", nameof(this.TryGetCredential)); errorData.Add("timeoutMs", timeoutMs); - errorData.Add("RepoUrl", repoUrl); + if (Uri.TryCreate(repoUrl, UriKind.Absolute, out Uri repoUri)) + { + errorData.Add("RepoAuthority", repoUri.Authority); + } + tracer.RelatedEvent( EventLevel.Warning, "CredentialFetchTimedOut", errorData, Keywords.Network | Keywords.Telemetry); TraceCredentialFillErrorOutput(tracer, gitCredentialOutput.Errors); + tracer.RelatedWarning(errorData, errorMessage); } else { @@ -1254,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) { @@ -1283,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) => { @@ -1290,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 @@ -1309,6 +1351,10 @@ protected virtual Result InvokeGitImpl( output.AppendLine(args.Data); } } + else + { + outputReadCompleted.Set(); + } }; } @@ -1414,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 @@ -1435,22 +1478,38 @@ 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(); + Stopwatch processWaitStopwatch = Stopwatch.StartNew(); if (!this.WaitForExitWithCancellation(timeoutMs, out bool cancellationRequested, cancellationToken)) { lock (this.processLock) @@ -1461,9 +1520,15 @@ protected virtual Result InvokeGitImpl( } } + Stopwatch killWaitStopwatch = Stopwatch.StartNew(); if (this.WaitForExitWithCancellation(ProcessKillTimeoutMs, out bool _)) { - this.executingProcess.WaitForExit(); + int killDrainTimeoutMs = GetRemainingTimeoutMs(ProcessKillTimeoutMs, killWaitStopwatch); + if (!WaitForOutputDrain(outputReadCompleted, errorReadCompleted, killDrainTimeoutMs, cancellationToken, out bool killDrainCanceled)) + { + this.CancelAsyncOutputReads(cancelOutput: true); + cancellationRequested |= killDrainCanceled; + } } if (cancellationRequested) @@ -1471,10 +1536,27 @@ protected virtual Result InvokeGitImpl( 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: " + errors.ToString(), Result.GenericFailureCode, output.Truncated, errors.Truncated, timedOut: true); } - this.executingProcess.WaitForExit(); + 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 while draining git output: " + terminationError + errors.ToString(), + Result.GenericFailureCode, + output.Truncated, + errors.Truncated, + timedOut: true); + } } } @@ -1491,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) @@ -1539,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}"; @@ -1752,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, @@ -1764,7 +1927,8 @@ private Result InvokeGitOutsideEnlistment( timeoutMs: timeout, usePreCommandHook: usePreCommandHook, mayRequireAuth: mayRequireAuth, - hasVisibleConsoleWindow: hasVisibleConsoleWindow); + hasVisibleConsoleWindow: hasVisibleConsoleWindow, + cancellationToken: cancellationToken); } /// @@ -1791,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, @@ -1801,7 +1966,8 @@ private Result InvokeGitAgainstDotGitFolderOrOutsideEnlistment( usePreCommandHook, timeoutMs, mayRequireAuth, - hasVisibleConsoleWindow); + hasVisibleConsoleWindow, + cancellationToken); } /// @@ -1819,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(); @@ -1833,7 +2000,8 @@ private Result InvokeGitAgainstDotGitFolderOrOutsideEnlistment( usePreCommandHook: usePreCommandHook, timeoutMs: timeoutMs, mayRequireAuth: mayRequireAuth, - hasVisibleConsoleWindow: hasVisibleConsoleWindow); + hasVisibleConsoleWindow: hasVisibleConsoleWindow, + cancellationToken: cancellationToken); } return this.InvokeGitOutsideEnlistment( @@ -1843,7 +2011,8 @@ private Result InvokeGitAgainstDotGitFolderOrOutsideEnlistment( timeout: timeoutMs, usePreCommandHook: usePreCommandHook, mayRequireAuth: mayRequireAuth, - hasVisibleConsoleWindow: hasVisibleConsoleWindow); + hasVisibleConsoleWindow: hasVisibleConsoleWindow, + cancellationToken: cancellationToken); } /// @@ -1900,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 @@ -1916,7 +2086,8 @@ private Result InvokeGitAgainstDotGitFolder( gitObjectsDirectory: gitObjectsDirectory, usePreCommandHook: usePreCommandHook, mayRequireAuth: mayRequireAuth, - hasVisibleConsoleWindow: hasVisibleConsoleWindow); + hasVisibleConsoleWindow: hasVisibleConsoleWindow, + cancellationToken: cancellationToken); } public class Result @@ -1929,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 1a578418ea..6c0bc542e8 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, out bool timedOut, 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, int timeoutMs = -1); + 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, int timeoutMs = -1); + 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 0be18adc01..556a35bc58 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 80d64030ec..b2c54cddcf 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 63fc0b0956..19c43b3247 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,12 @@ 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) @@ -152,14 +163,17 @@ protected GitEndPointResponseData SendRequest( out authString, out errorMessage, out bool credentialFetchTimedOut, - this.CredentialTimeoutMs)) + this.CredentialTimeoutMs, + cancellationToken)) { return new GitEndPointResponseData( HttpStatusCode.Unauthorized, new GitObjectsHttpException(HttpStatusCode.Unauthorized, errorMessage), shouldRetry: !credentialFetchTimedOut, message: null, - onResponseDisposed: null); + onResponseDisposed: null, + shouldRecordFailure: !credentialFetchTimedOut, + credentialFetchTimedOut: credentialFetchTimedOut); } // Initialization may finish anonymously while this request waits. @@ -223,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(); @@ -254,7 +272,7 @@ protected GitEndPointResponseData SendRequest( if (!sendAnonymous) { - this.authentication.ApproveCredentials(this.Tracer, authString, this.CredentialTimeoutMs); + this.authentication.ApproveCredentials(this.Tracer, authString, this.CredentialTimeoutMs, cancellationToken); } else if (!forceAnonymous) { @@ -273,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)) @@ -310,28 +330,46 @@ protected GitEndPointResponseData SendRequest( } else if (ShouldRejectCredentials(response.StatusCode, errorMessage)) { - this.authentication.RejectCredentials(this.Tracer, authString, this.CredentialTimeoutMs); - 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) @@ -381,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(); + } } } @@ -564,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 c4e8b5ca27..18672e7eee 100644 --- a/GVFS/GVFS.Common/RetryConfig.cs +++ b/GVFS/GVFS.Common/RetryConfig.cs @@ -19,6 +19,7 @@ public class RetryConfig /// 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); @@ -134,13 +135,15 @@ public static bool TryLoadFromGitConfig(ITracer tracer, GitProcess git, out Retr { "MaxRetries", retryConfig.MaxRetries }, { "CredentialTimeoutMs", retryConfig.CredentialTimeoutMs }, { TracingConstants.MessageKey.InfoMessage, "RetryConfigLoaded" } - }); + }, + Keywords.Telemetry); } return true; } - private static bool TryLoadMaxRetries(GitProcess git, out int attempts, out string error) { + private static bool TryLoadMaxRetries(GitProcess git, out int attempts, out string error) + { return TryGetFromGitConfig( git, GVFSConstants.GitConfig.MaxRetriesConfig, @@ -190,6 +193,16 @@ private static bool TryLoadCredentialTimeoutMs(GitProcess git, out int credentia 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; } diff --git a/GVFS/GVFS.Platform.Windows/WindowsPlatform.cs b/GVFS/GVFS.Platform.Windows/WindowsPlatform.cs index a27c980834..1620986e30 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 de15ac1a27..c0eb20ef24 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 c418ff74e7..e4040b15e2 100644 --- a/GVFS/GVFS.UnitTests/Common/RetryConfigTests.cs +++ b/GVFS/GVFS.UnitTests/Common/RetryConfigTests.cs @@ -132,6 +132,25 @@ public void TryLoadConfigTreatsNonPositiveCredentialTimeoutAsUnbounded() 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() { @@ -140,5 +159,14 @@ public void RetryConfigDefaultsCredentialTimeoutWhenNotLoadedFromConfig() 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 0d522bb5c8..5acf7c2564 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 4995577719..79a2820902 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 96777c7004..d267f695c3 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 1e7236202e..1b1e6320f0 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 e81b81170d..9c648ab1d3 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 6fb128930d..ab5d5dafe4 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 3272726519..c7e4c2d82c 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 { @@ -44,12 +45,19 @@ public MockGitProcess(string gitBinPath, string workingDirectoryRoot) /// 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; } + 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>(); @@ -84,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, int timeoutMs = -1) + 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); @@ -101,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, timeoutMs); + 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, int timeoutMs = -1) + 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); @@ -121,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, timeoutMs); + return base.TryDeleteCredential(tracer, repoUrl, username, password, out error, out timedOut, timeoutMs, cancellationToken); } protected override Result InvokeGitImpl( @@ -136,13 +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) {