diff --git a/GVFS/GVFS.Common/Git/GitProcess.cs b/GVFS/GVFS.Common/Git/GitProcess.cs index a193d92fb..ac8a1eb3d 100644 --- a/GVFS/GVFS.Common/Git/GitProcess.cs +++ b/GVFS/GVFS.Common/Git/GitProcess.cs @@ -40,6 +40,8 @@ public class GitProcess : ICredentialStore private const string MissingPasswordErrorMessage = "Git credential fill returned no password"; private const int MaxCredentialOutputKeys = 32; private const int MaxCredentialOutputKeyLength = 32; + private const int MaxCredentialConfigReadAttempts = 5; + private const int CredentialConfigReadRetryDelayMs = 20; private static readonly Encoding UTF8NoBOM = new UTF8Encoding(false); @@ -319,13 +321,11 @@ public virtual bool TryGetCertificatePassword( // See GetFromConfig for why pre-command hook is disabled // for bootstrap-time git operations. - Result gitCredentialOutput = this.InvokeGitAgainstDotGitFolder( + Result gitCredentialOutput = this.InvokeCredentialFill( + tracer, "credential fill", - stdin => stdin.Write("protocol=cert\npath=" + certificatePath + "\nusername=\n\n"), - parseStdOutLine: null, - usePreCommandHook: false, - mayRequireAuth: true, - hasVisibleConsoleWindow: hasVisibleConsoleWindow); + "protocol=cert\npath=" + certificatePath + "\nusername=\n\n", + hasVisibleConsoleWindow); if (gitCredentialOutput.ExitCodeIsFailure) { @@ -386,14 +386,12 @@ public virtual bool TryGetCredential( // See GetFromConfig for why pre-command hook is disabled // for bootstrap-time git operations. - Result gitCredentialOutput = this.InvokeGitAgainstDotGitFolder( + Result gitCredentialOutput = this.InvokeCredentialFill( + tracer, GenerateCredentialVerbCommand("fill"), - stdin => stdin.Write($"url={repoUrl}\n\n"), - parseStdOutLine: null, - usePreCommandHook: false, - timeoutMs: timeoutMs, - mayRequireAuth: true, - hasVisibleConsoleWindow: hasVisibleConsoleWindow); + $"url={repoUrl}\n\n", + hasVisibleConsoleWindow, + timeoutMs); if (gitCredentialOutput.ExitCodeIsFailure) { @@ -1147,6 +1145,9 @@ protected virtual Result InvokeGitImpl( return new Result(output.ToString(), "Operation timed out: " + errors.ToString(), Result.GenericFailureCode, output.Truncated, errors.Truncated); } + + // A timed wait does not wait for redirected-stream callbacks to finish. + this.executingProcess.WaitForExit(); } return new Result(output.ToString(), errors.ToString(), this.executingProcess.ExitCode, output.Truncated, errors.Truncated); @@ -1181,6 +1182,108 @@ private static bool CurrentProcessHasVisibleConsoleWindowSafe() } } + private Result InvokeCredentialFill( + ITracer tracer, + string command, + string input, + bool hasVisibleConsoleWindow, + int timeoutMs = Timeout.Infinite) + { + Stopwatch timer = Stopwatch.StartNew(); + int remainingTimeoutMs = timeoutMs; + for (int attempt = 1; ; ++attempt) + { + Result result = this.InvokeGitAgainstDotGitFolder( + command, + stdin => stdin.Write(input), + parseStdOutLine: null, + usePreCommandHook: false, + timeoutMs: remainingTimeoutMs, + mayRequireAuth: true, + hasVisibleConsoleWindow: hasVisibleConsoleWindow); + + if (!IsCredentialConfigReadFailure(result)) + { + return result; + } + + int delayMs = CredentialConfigReadRetryDelayMs << (attempt - 1); + bool willRetry = attempt < MaxCredentialConfigReadAttempts && + (timeoutMs == Timeout.Infinite || timeoutMs - timer.ElapsedMilliseconds > delayMs); + tracer.RelatedEvent( + EventLevel.Warning, + "CredentialConfigReadFailure", + new EventMetadata + { + { "AttemptNumber", attempt }, + { "MaxAttempts", MaxCredentialConfigReadAttempts }, + { "WillRetry", willRetry }, + { "RetryDelayMilliseconds", willRetry ? delayMs : 0 }, + }, + Keywords.Network | Keywords.Telemetry); + + if (!willRetry) + { + return result; + } + + TraceCredentialFillErrorOutput(tracer, result.Errors); + Thread.Sleep(delayMs); + if (timeoutMs != Timeout.Infinite) + { + remainingTimeoutMs = (int)Math.Max(0, timeoutMs - timer.ElapsedMilliseconds); + } + } + } + + private static bool IsCredentialConfigReadFailure(Result result) + { + if (!result.ExitCodeIsFailure || result.ErrorsTruncated || result.OutputTruncated || + !string.IsNullOrEmpty(result.Output)) + { + return false; + } + + // Only retry Git's config-read failure, not a credential helper or prompt failure. + bool configReadFailed = false; + bool transientAccessFailure = false; + foreach (string errorLine in result.Errors.Split('\n')) + { + string line = errorLine.TrimEnd('\r'); + if (line.Length == 0) + { + continue; + } + + if (line == "fatal: unknown error occurred while reading the configuration files") + { + configReadFailed = true; + } + else if (line.StartsWith("warning: unable to access '", StringComparison.Ordinal)) + { + int separator = line.LastIndexOf("': ", StringComparison.Ordinal); + if (separator < 0) + { + return false; + } + + string reason = line.Substring(separator + 3); + if (reason != "Permission denied" && reason != "Device or resource busy") + { + return false; + } + + transientAccessFailure = true; + } + else + { + return false; + } + } + + return configReadFailed && transientAccessFailure; + } + private static void AddCredentialFillResult(EventMetadata data, Result result) { // Describes the failure without the text of stderr, which can contain a secret. diff --git a/GVFS/GVFS.UnitTests/Common/Git/GitProcessCredentialTests.cs b/GVFS/GVFS.UnitTests/Common/Git/GitProcessCredentialTests.cs index 64e30f309..c3abf7178 100644 --- a/GVFS/GVFS.UnitTests/Common/Git/GitProcessCredentialTests.cs +++ b/GVFS/GVFS.UnitTests/Common/Git/GitProcessCredentialTests.cs @@ -4,7 +4,11 @@ using GVFS.UnitTests.Mock.Common; using GVFS.UnitTests.Mock.Git; using NUnit.Framework; +using System; +using System.Collections.Generic; +using System.IO; using System.Linq; +using System.Threading; namespace GVFS.UnitTests.Common.Git { @@ -17,6 +21,178 @@ public class GitProcessCredentialTests private const string CertificateFillCommand = "credential fill"; private const string MissingPasswordMessage = "Git credential fill returned no password"; private const int GitFatalExitCode = 128; + private const string ConfigReadFailure = + "warning: unable to access 'mock/config': Permission denied\n" + + "fatal: unknown error occurred while reading the configuration files\n"; + + [TestCase(false, "Permission denied", "\n")] + [TestCase(true, "Permission denied", "\n")] + [TestCase(false, "Device or resource busy", "\r\n")] + [TestCase(true, "Device or resource busy", "\r\n")] + public void CredentialFillRetriesAConfigReadFailure(bool certificate, string reason, string lineEnding) + { + MockTracer tracer = new MockTracer(); + MockGitProcess gitProcess = new MockGitProcess(); + int attempts = 0; + gitProcess.SetExpectedCommandResult( + certificate ? CertificateFillCommand : CredentialFillCommand, + () => ++attempts == 1 + ? new GitProcess.Result(string.Empty, ConfigReadFailure.Replace("Permission denied", reason).Replace("\n", lineEnding), GitFatalExitCode) + : new GitProcess.Result("username=someone\npassword=" + SecretValue + "\n", string.Empty, GitProcess.Result.SuccessCode)); + + string password; + string error; + bool success = certificate + ? gitProcess.TryGetCertificatePassword(tracer, "mock://certificate", out password, out error) + : gitProcess.TryGetCredential(tracer, "mock://repoUrl", out _, out password, out error); + + success.ShouldBeTrue(error); + password.ShouldEqual(SecretValue); + attempts.ShouldEqual(2); + gitProcess.InvocationsRun.Select(i => i.TimeoutMs).ShouldMatchInOrder(-1, -1); + tracer.RelatedEventNames.ShouldMatchInOrder("CredentialConfigReadFailure"); + ((bool)tracer.RelatedEventMetadata[0]["WillRetry"]).ShouldBeTrue(); + AssertConfigReadFailureTelemetry(tracer); + AssertNoSecret(tracer); + } + + [TestCase] + public void CredentialFillStopsAfterTheConfigRetryBudget() + { + MockTracer tracer = new MockTracer(); + MockGitProcess gitProcess = CreateGitProcess(CredentialFillCommand, string.Empty, ConfigReadFailure, GitFatalExitCode); + + gitProcess.TryGetCredential(tracer, "mock://repoUrl", out _, out _, out string error).ShouldBeFalse(); + + gitProcess.InvocationsRun.Count.ShouldEqual(5); + tracer.RelatedEventMetadata.Select(e => (bool)e["WillRetry"]).ShouldMatchInOrder(true, true, true, true, false); + tracer.RelatedEventMetadata.Select(e => (int)e["AttemptNumber"]).ShouldMatchInOrder(1, 2, 3, 4, 5); + tracer.RelatedEventMetadata.Select(e => (int)e["MaxAttempts"]).ShouldMatchInOrder(5, 5, 5, 5, 5); + tracer.RelatedEventMetadata.Select(e => (int)e["RetryDelayMilliseconds"]).ShouldMatchInOrder(20, 40, 80, 160, 0); + AssertConfigReadFailureTelemetry(tracer); + AssertErrorMessageHasNoStderr(error); + tracer.RelatedWarningEvents.Any(e => e.Contains("Permission denied")).ShouldBeTrue(); + } + + [TestCase("fatal: Authentication failed\n", "", false, false)] + [TestCase("Operation timed out after 5000ms", "", false, false)] + [TestCase("warning: unable to access 'mock/config': Permission denied\nfatal: Authentication failed\n", "", false, false)] + [TestCase("warning: unable to access 'mock/Permission denied': Invalid argument\nfatal: unknown error occurred while reading the configuration files\n", "", false, false)] + [TestCase(ConfigReadFailure, "username=someone\n", false, false)] + [TestCase(ConfigReadFailure, "", true, false)] + [TestCase(ConfigReadFailure, "", false, true)] + [TestCase(ConfigReadFailure + "fatal: credential helper 'mock-helper' told us to quit\n", "", false, false)] + [TestCase(ConfigReadFailure + "fatal: Authentication failed\n", "", false, false)] + [TestCase(ConfigReadFailure + "warning: unable to access 'mock/other-config': Invalid argument\n", "", false, false)] + public void CredentialFillDoesNotRetryOtherFailures(string errors, string output, bool outputTruncated, bool errorsTruncated) + { + MockTracer tracer = new MockTracer(); + MockGitProcess gitProcess = new MockGitProcess(); + gitProcess.SetExpectedCommandResult( + CredentialFillCommand, + () => new GitProcess.Result(output, errors, GitFatalExitCode, outputTruncated, errorsTruncated)); + + gitProcess.TryGetCredential(tracer, "mock://repoUrl", out _, out _, out _).ShouldBeFalse(); + + gitProcess.InvocationsRun.Count.ShouldEqual(1); + tracer.RelatedEventNames.ShouldBeEmpty(); + } + + [TestCase] + public void CredentialFillDoesNotRestartTheTimeoutBudget() + { + MockTracer tracer = new MockTracer(); + MockGitProcess gitProcess = new MockGitProcess(); + gitProcess.SetExpectedCommandResult( + CredentialFillCommand, + () => gitProcess.InvocationsRun.Count == 1 + ? new GitProcess.Result(string.Empty, ConfigReadFailure, GitFatalExitCode) + : new GitProcess.Result("password=" + SecretValue + "\n", string.Empty, GitProcess.Result.SuccessCode)); + + gitProcess.TryGetCredential(tracer, "mock://repoUrl", out _, out _, out string error, timeoutMs: 5000).ShouldBeTrue(error); + + gitProcess.InvocationsRun.Count.ShouldEqual(2); + gitProcess.InvocationsRun[0].TimeoutMs.ShouldEqual(5000); + gitProcess.InvocationsRun[1].TimeoutMs.ShouldBeAtMost(4999); + } + + [TestCase(false)] + [TestCase(true)] + public void CredentialFillDoesNotRetryATimeoutWithConfigDiagnostics(bool afterConfigFailure) + { + MockTracer tracer = new MockTracer(); + MockGitProcess gitProcess = new MockGitProcess(); + gitProcess.SetExpectedCommandResult( + CredentialFillCommand, + () => afterConfigFailure && gitProcess.InvocationsRun.Count == 1 + ? new GitProcess.Result(string.Empty, ConfigReadFailure, GitFatalExitCode) + : new GitProcess.Result(string.Empty, "Operation timed out: " + ConfigReadFailure, GitProcess.Result.GenericFailureCode)); + + gitProcess.TryGetCredential(tracer, "mock://repoUrl", out _, out _, out string error, timeoutMs: 5000).ShouldBeFalse(); + + gitProcess.InvocationsRun.Count.ShouldEqual(afterConfigFailure ? 2 : 1); + error.ShouldEqual("Credential manager did not respond within 5 seconds"); + } + + [TestCase] + public void CredentialFillDoesNotRetryWhenTheTimeoutCannotCoverTheDelay() + { + MockTracer tracer = new MockTracer(); + MockGitProcess gitProcess = CreateGitProcess(CredentialFillCommand, string.Empty, ConfigReadFailure, GitFatalExitCode); + + gitProcess.TryGetCredential(tracer, "mock://repoUrl", out _, out _, out _, timeoutMs: 1).ShouldBeFalse(); + + gitProcess.InvocationsRun.Count.ShouldEqual(1); + ((bool)tracer.RelatedEventMetadata.Single()["WillRetry"]).ShouldBeFalse(); + } + + [TestCase(true, 30000)] + [TestCase(false, 30000)] + [TestCase(true, Timeout.Infinite)] + [TestCase(false, Timeout.Infinite)] + public void CredentialFillHandlesARealLockedGitConfig(bool releaseAfterFirstAttempt, int timeoutMs) + { + string gitPath = Path.Combine(Environment.GetFolderPath(Environment.SpecialFolder.ProgramFiles), "Git", "cmd", "git.exe"); + if (!File.Exists(gitPath)) + { + Assert.Ignore("Git is not installed at the expected path."); + } + + string repoPath = Path.Combine(Path.GetTempPath(), nameof(GitProcessCredentialTests) + Guid.NewGuid().ToString("N")); + string dotGit = Path.Combine(repoPath, ".git"); + Directory.CreateDirectory(Path.Combine(dotGit, "objects")); + Directory.CreateDirectory(Path.Combine(dotGit, "refs", "heads")); + try + { + File.WriteAllText(Path.Combine(dotGit, "HEAD"), "ref: refs/heads/main\n"); + File.WriteAllText(Path.Combine(dotGit, "config"), "[core]\n\trepositoryformatversion = 0\n\tbare = false\n"); + LockedConfigGitProcess gitProcess = new LockedConfigGitProcess(gitPath, repoPath, releaseAfterFirstAttempt); + MockTracer tracer = new MockTracer(); + + bool success = gitProcess.TryGetCredential(tracer, "mock://repoUrl", out string username, out string password, out string error, timeoutMs: timeoutMs); + + success.ShouldEqual(releaseAfterFirstAttempt, error); + gitProcess.Results.Count.ShouldEqual(releaseAfterFirstAttempt ? 2 : 5); + gitProcess.Results[0].ExitCode.ShouldEqual(GitFatalExitCode); + gitProcess.Results[0].Errors.ShouldContain("Permission denied"); + gitProcess.Results[0].Errors.ShouldContain("unknown error occurred while reading the configuration files"); + if (releaseAfterFirstAttempt) + { + username.ShouldEqual("someone"); + password.ShouldEqual(SecretValue); + } + else + { + AssertErrorMessageHasNoStderr(error); + } + + AssertNoSecret(tracer); + } + finally + { + Directory.Delete(repoPath, recursive: true); + } + } [TestCase] public void TryGetCredentialDoesNotTraceSecretWhenThePasswordIsMissing() @@ -254,6 +430,16 @@ public void TryGetCredentialFailsWhenNoLineStartsWithThePasswordKey(string outpu password.ShouldBeNull(); } + private static void AssertConfigReadFailureTelemetry(MockTracer tracer) + { + foreach (EventMetadata metadata in tracer.RelatedEventMetadata) + { + CollectionAssert.AreEquivalent( + new[] { "AttemptNumber", "MaxAttempts", "WillRetry", "RetryDelayMilliseconds" }, + metadata.Keys); + } + } + private static MockGitProcess CreateGitProcess( string command, string output, @@ -268,6 +454,58 @@ private static MockGitProcess CreateGitProcess( return gitProcess; } + private sealed class LockedConfigGitProcess : GitProcess + { + private readonly string configPath; + private readonly bool releaseAfterFirstAttempt; + + public LockedConfigGitProcess(string gitPath, string repoPath, bool releaseAfterFirstAttempt) + : base(gitPath, repoPath) + { + this.configPath = Path.Combine(repoPath, ".git", "config"); + this.releaseAfterFirstAttempt = releaseAfterFirstAttempt; + } + + public List Results { get; } = new List(); + + protected override Result InvokeGitImpl( + string command, + string workingDirectory, + string dotGitDirectory, + bool useReadObjectHook, + Action writeStdIn, + Action parseStdOutLine, + int timeoutMs, + string gitObjectsDirectory = null, + bool usePrecommandHook = true, + bool mayRequireAuth = false, + bool? hasVisibleConsoleWindow = null) + { + // Replace all credential helpers with a local, deterministic helper. No credentials leave the test. + string isolatedCommand = "-c credential.helper= -c credential.helper=\"!f() { echo username=someone; echo password=" + + SecretValue + "; }; f\" " + command; + using (FileStream configLock = this.Results.Count == 0 || !this.releaseAfterFirstAttempt + ? File.Open(this.configPath, FileMode.Open, FileAccess.Read, FileShare.None) + : null) + { + Result result = base.InvokeGitImpl( + isolatedCommand, + workingDirectory, + dotGitDirectory, + useReadObjectHook, + writeStdIn, + parseStdOutLine, + timeoutMs, + gitObjectsDirectory, + usePrecommandHook, + mayRequireAuth, + hasVisibleConsoleWindow); + this.Results.Add(result); + return result; + } + } + } + private static void AssertErrorMessageHasNoStderr(string errorMessage) { // The caller puts this message in an exception, and the retry handler reports exceptions diff --git a/GVFS/GVFS.UnitTests/Git/GitProcessTests.cs b/GVFS/GVFS.UnitTests/Git/GitProcessTests.cs index b2b2efe03..85668c6ad 100644 --- a/GVFS/GVFS.UnitTests/Git/GitProcessTests.cs +++ b/GVFS/GVFS.UnitTests/Git/GitProcessTests.cs @@ -3,8 +3,11 @@ using GVFS.UnitTests.Mock.Common; using GVFS.UnitTests.Mock.Git; using NUnit.Framework; +using System; using System.Diagnostics; using System.IO; +using System.Threading; +using System.Threading.Tasks; namespace GVFS.UnitTests.Git { @@ -384,6 +387,45 @@ public void QuoteGitPath(string input, string expected) GitProcess.QuoteGitPath(input).ShouldEqual(expected); } + [TestCase(30000)] + [TestCase(Timeout.Infinite)] + public void GitCommandWaitsForOutputCallbacks(int timeoutMs) + { + string gitPath = Path.Combine(Environment.GetFolderPath(Environment.SpecialFolder.ProgramFiles), "Git", "cmd", "git.exe"); + if (!File.Exists(gitPath)) + { + Assert.Ignore("Git is not installed at the expected path."); + } + + OutputCallbackGitProcess gitProcess = new OutputCallbackGitProcess(gitPath); + using (ManualResetEventSlim callbackStarted = new ManualResetEventSlim()) + using (ManualResetEventSlim releaseCallback = new ManualResetEventSlim()) + { + bool callbackCompleted = false; + Task command = Task.Run(() => gitProcess.GetVersion( + line => + { + callbackStarted.Set(); + callbackCompleted = releaseCallback.Wait(TimeSpan.FromSeconds(10)); + }, + timeoutMs)); + + try + { + callbackStarted.Wait(TimeSpan.FromSeconds(10)).ShouldBeTrue("Git did not produce output"); + command.Wait(TimeSpan.FromSeconds(1)).ShouldBeFalse("The command returned before its output callback finished"); + } + finally + { + releaseCallback.Set(); + command.Wait(TimeSpan.FromSeconds(10)).ShouldBeTrue("The command did not finish after its output callback was released"); + } + + command.Result.ExitCode.ShouldEqual(0); + callbackCompleted.ShouldBeTrue(); + } + } + [TestCase] [Description("Integration test: verify QuoteGitPath produces arguments that git actually receives correctly")] public void QuoteGitPath_RoundTripThroughProcess() @@ -436,5 +478,26 @@ public void QuoteGitPath_RoundTripThroughProcess() } } } + + private sealed class OutputCallbackGitProcess : GitProcess + { + public OutputCallbackGitProcess(string gitPath) + : base(gitPath, workingDirectoryRoot: null) + { + } + + public Result GetVersion(Action onOutput, int timeoutMs) + { + return this.InvokeGitImpl( + "--version", + workingDirectory: null, + dotGitDirectory: null, + useReadObjectHook: false, + writeStdIn: null, + parseStdOutLine: onOutput, + timeoutMs: timeoutMs, + usePreCommandHook: false); + } + } } } diff --git a/GVFS/GVFS.UnitTests/Mock/Git/MockGitProcess.cs b/GVFS/GVFS.UnitTests/Mock/Git/MockGitProcess.cs index 1eeb7996a..1f1854c8a 100644 --- a/GVFS/GVFS.UnitTests/Mock/Git/MockGitProcess.cs +++ b/GVFS/GVFS.UnitTests/Mock/Git/MockGitProcess.cs @@ -121,7 +121,7 @@ protected override Result InvokeGitImpl( bool? hasVisibleConsoleWindow = null) { this.CommandsRun.Add(command); - this.InvocationsRun.Add(new GitInvocation(command, dotGitDirectory, mayRequireAuth, hasVisibleConsoleWindow)); + this.InvocationsRun.Add(new GitInvocation(command, dotGitDirectory, mayRequireAuth, hasVisibleConsoleWindow, timeoutMs)); if (this.ShouldFail) { @@ -162,12 +162,13 @@ protected override Result InvokeGitImpl( public class GitInvocation { - public GitInvocation(string command, string dotGitDirectory, bool mayRequireAuth, bool? hasVisibleConsoleWindow) + public GitInvocation(string command, string dotGitDirectory, bool mayRequireAuth, bool? hasVisibleConsoleWindow, int timeoutMs) { this.Command = command; this.DotGitDirectory = dotGitDirectory; this.MayRequireAuth = mayRequireAuth; this.HasVisibleConsoleWindow = hasVisibleConsoleWindow; + this.TimeoutMs = timeoutMs; } public string Command { get; } @@ -176,6 +177,7 @@ public GitInvocation(string command, string dotGitDirectory, bool mayRequireAuth public string DotGitDirectory { get; } public bool MayRequireAuth { get; } public bool? HasVisibleConsoleWindow { get; } + public int TimeoutMs { get; } } public class Credential