From 5390bfe98382f791706523f2f02729257ec8f721 Mon Sep 17 00:00:00 2001 From: Scott Beddall <45376673+scbedd@users.noreply.github.com> Date: Wed, 22 Mar 2023 13:07:18 -0700 Subject: [PATCH] Add retry on specific git output (#5747) * add retry based on git output. error 429 and timeouts are now retried twice before we give up --- .../GitProcessHandlerTests.cs | 56 +++++ .../Store/GitProcessHandler.cs | 229 ++++++++++++------ 2 files changed, 213 insertions(+), 72 deletions(-) diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/GitProcessHandlerTests.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/GitProcessHandlerTests.cs index de32d03f64b..fa962ad8a45 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/GitProcessHandlerTests.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/GitProcessHandlerTests.cs @@ -15,6 +15,62 @@ public GitProcessHandlerTests() DebugLogger.ConfigureLogger(loggerFactory); } + const string longTimeOutError = @" + Cloning into '.'... + fatal: unable to access 'https://github.com/Azure/azure-sdk-assets/': Failed to connect to github.com port 443: Operation timed out + + + at Azure.Sdk.Tools.TestProxy.Store.GitStore.InitializeAssetsRepo(GitAssetsConfiguration config, Boolean forceInit) in /mnt/vss/_work/1/s/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Store/GitStore.cs:line 456 + at Azure.Sdk.Tools.TestProxy.Store.GitStore.Restore(String pathToAssetsJson) in /mnt/vss/_work/1/s/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Store/GitStore.cs:line 152 + at Azure.Sdk.Tools.TestProxy.Startup.Run(Object commandObj) in /mnt/vss/_work/1/s/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Startup.cs:line 154 + at CommandLine.ParserResultExtensions.WithParsedAsync[T](ParserResult`1 result, Func`2 action) + at Azure.Sdk.Tools.TestProxy.Startup.Main(String[] args) in /mnt/vss/_work/1/s/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Startup.cs:line 67 + at Azure.Sdk.Tools.TestProxy.Startup.
(String[] args)"; + + const string tooManyRequestsError = @"fatal: unable to access 'https://github.com/Azure/azure-sdk-assets/': The requested URL returned error: 429 + fatal: could not fetch 26bfd3d8ada54a78573cb64f6fa79c8d4a300c8c from promisor remote + + at Azure.Sdk.Tools.TestProxy.Store.GitStore.CheckoutRepoAtConfig(GitAssetsConfiguration config) in /mnt/vss/_work/1/s/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Store/GitStore.cs:line 330 + at Azure.Sdk.Tools.TestProxy.Store.GitStore.InitializeAssetsRepo(GitAssetsConfiguration config, Boolean forceInit) in /mnt/vss/_work/1/s/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Store/GitStore.cs:line 459 + at Azure.Sdk.Tools.TestProxy.Store.GitStore.Restore(String pathToAssetsJson) in /mnt/vss/_work/1/s/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Store/GitStore.cs:line 152 + at Azure.Sdk.Tools.TestProxy.RecordingHandler.RestoreAssetsJson(String assetsJson, Boolean forceCheckout) in /mnt/vss/_work/1/s/tools/test-proxy/Azure.Sdk.Tools.TestProxy/RecordingHandler.cs:line 164 + at Azure.Sdk.Tools.TestProxy.RecordingHandler.StartPlaybackAsync(String sessionId, HttpResponse outgoingResponse, RecordingType mode, String assetsPath) in /mnt/vss/_work/1/s/tools/test-proxy/Azure.Sdk.Tools.TestProxy/RecordingHandler.cs:line 373 + at Azure.Sdk.Tools.TestProxy.Playback.Start() in /mnt/vss/_work/1/s/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Playback.cs:line 46 + at lambda_method37(Closure , Object )"; + + const string longTimeOutWithValue = @"fatal: unable to access 'https://github.com/Azure/azure-sdk-assets/': Failed to connect to github.com port 443 after 21019 ms: Couldn't connect to server + fatal: could not fetch 87d05b71fcffcf3c7fa8e611bda09b505ff586a4 from promisor remote + + + at Azure.Sdk.Tools.TestProxy.Store.GitStore.CheckoutRepoAtConfig(GitAssetsConfiguration config) in /mnt/vss/_work/1/s/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Store/GitStore.cs:line 330 + at Azure.Sdk.Tools.TestProxy.Store.GitStore.InitializeAssetsRepo(GitAssetsConfiguration config, Boolean forceInit) in /mnt/vss/_work/1/s/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Store/GitStore.cs:line 459 + at Azure.Sdk.Tools.TestProxy.Store.GitStore.Restore(String pathToAssetsJson) in /mnt/vss/_work/1/s/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Store/GitStore.cs:line 152 + at Azure.Sdk.Tools.TestProxy.RecordingHandler.RestoreAssetsJson(String assetsJson, Boolean forceCheckout) in /mnt/vss/_work/1/s/tools/test-proxy/Azure.Sdk.Tools.TestProxy/RecordingHandler.cs:line 164 + at Azure.Sdk.Tools.TestProxy.RecordingHandler.StartPlaybackAsync(String sessionId, HttpResponse outgoingResponse, RecordingType mode, String assetsPath) in /mnt/vss/_work/1/s/tools/test-proxy/Azure.Sdk.Tools.TestProxy/RecordingHandler.cs:line 373 + at Azure.Sdk.Tools.TestProxy.Playback.Start() in /mnt/vss/_work/1/s/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Playback.cs:line 46 + at lambda_method37(Closure , Object )"; + + [Theory] + [InlineData("", longTimeOutError, 1, true)] + [InlineData("", tooManyRequestsError, 1, true)] + [InlineData("", longTimeOutWithValue, 1, true)] + [InlineData("", "fatal: unable to access 'https://github.com/Azure/azure-sdk-assets/': Failed to connect to github.com port 443 after 1 ms: Couldn't connect to server", 1, true)] + [InlineData("", "fatal: unable to access 'https://github.com/Azure/azure-sdk-assets/': Failed to connect to github.com port 443 after 0 ms: Couldn't connect to server", 1, true)] + [InlineData("", "fatal: unable to access 'https://github.com/Azure/azure-sdk-assets/': Failed to connect to github.com port 443 after ms: Couldn't connect to server", 1, false)] + [InlineData("", "", 0, false)] + public void VerifyGitExceptionParser(string inputStdOut, string inputStdErr, int exitCode, bool expectedResult) + { + var processHandler = new GitProcessHandler(); + var commandResult = new CommandResult(); + commandResult.StdOut = inputStdOut; + commandResult.StdErr = inputStdErr; + commandResult.ExitCode = exitCode; + + var checkResult = processHandler.IsRetriableGitError(commandResult); + + Assert.Equal(expectedResult, checkResult); + } + [Theory] // 2.37.0 is the min version of git required by the TestProxy // Windows git version strings diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Store/GitProcessHandler.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Store/GitProcessHandler.cs index b77604f26fe..fd4581b0d3c 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Store/GitProcessHandler.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Store/GitProcessHandler.cs @@ -1,5 +1,4 @@ using System; -using System.Collections; using System.Collections.Concurrent; using System.Collections.Generic; using System.Diagnostics; @@ -21,11 +20,13 @@ public class CommandResult public Exception CommandException; } + /// /// This class offers an easy wrapper abstraction for shelling out to git. /// public class GitProcessHandler { + public const int RETRY_INTERMITTENT_FAILURE_COUNT = 3; /// /// Internal class to hold the minimum supported version of git. If that /// version changes we only need to change it here. @@ -127,54 +128,73 @@ public virtual CommandResult Run(string arguments, string workingDirectory) { try { - DebugLogger.LogInformation($"git {arguments}"); - - var output = new List(); - var error = new List(); - - using (var process = new Process()) + int attempts = 1; + while (attempts <= RETRY_INTERMITTENT_FAILURE_COUNT) { - process.StartInfo = processStartInfo; + DebugLogger.LogInformation($"git {arguments}"); + + var output = new List(); + var error = new List(); - process.OutputDataReceived += (s, e) => + using (var process = new Process()) { - lock (output) + process.StartInfo = processStartInfo; + + process.OutputDataReceived += (s, e) => { - output.Add(e.Data); - } - }; + lock (output) + { + output.Add(e.Data); + } + }; - process.ErrorDataReceived += (s, e) => - { - lock (error) + process.ErrorDataReceived += (s, e) => { - error.Add(e.Data); + lock (error) + { + error.Add(e.Data); + } + }; + + process.Start(); + process.BeginErrorReadLine(); + process.BeginOutputReadLine(); + process.WaitForExit(); + + int returnCode = process.ExitCode; + var stdOut = string.Join(Environment.NewLine, output); + var stdError = string.Join(Environment.NewLine, error); + + DebugLogger.LogDebug($"StdOut: {stdOut}"); + DebugLogger.LogDebug($"StdErr: {stdError}"); + DebugLogger.LogDebug($"ExitCode: {process.ExitCode}"); + + result.ExitCode = process.ExitCode; + result.StdErr = string.Join(Environment.NewLine, stdError); + result.StdOut = string.Join(Environment.NewLine, stdOut); + + if (result.ExitCode == 0) + { + break; } - }; - - process.Start(); - process.BeginErrorReadLine(); - process.BeginOutputReadLine(); - process.WaitForExit(); - - int returnCode = process.ExitCode; - var stdOut = string.Join(Environment.NewLine, output); - var stdError = string.Join(Environment.NewLine, error); + var continueToAttempt = IsRetriableGitError(result); - DebugLogger.LogDebug($"StdOut: {stdOut}"); - DebugLogger.LogDebug($"StdErr: {stdError}"); - DebugLogger.LogDebug($"ExitCode: {process.ExitCode}"); + if (!continueToAttempt) + { + throw new GitProcessException(result); + } - result.ExitCode = process.ExitCode; - result.StdErr = string.Join(Environment.NewLine, stdError); - result.StdOut = string.Join(Environment.NewLine, stdOut); + attempts++; - if (result.ExitCode != 0) - { - throw new GitProcessException(result); + if (continueToAttempt && attempts < RETRY_INTERMITTENT_FAILURE_COUNT) + { + Task.Delay(attempts * 2 * 1000).Wait(); + } } } } + // exceptions caught here will be to do with inability to start the git process + // otherwise all "error" states should be handled by the output to stdErr and non-zero exitcode. catch (Exception e) { DebugLogger.LogDebug(e.Message); @@ -189,6 +209,52 @@ public virtual CommandResult Run(string arguments, string workingDirectory) return result; } + /// + /// This function evaluates a git command invocation result. The result of "yes you should retry this" only occurs + /// when the necessary data is available. Otherwise we default to NOT retry. + /// + /// Check Azure/azure-sdk-tools#5660 for additional detail on occurrence. + /// + /// + /// + public bool IsRetriableGitError(CommandResult result) + { + if (result.ExitCode != 0) { + // we cannot evaluate an empty stderr to see if it is retriable + if (string.IsNullOrEmpty(result.StdErr)) + { + return false; + } + + // fatal: unable to access 'https://github.com/Azure/azure-sdk-assets/': The requested URL returned error: 429 + if (result.StdErr.Contains("The requested URL returned error: 429")) + { + return true; + } + + // fatal: unable to access 'https://github.com/Azure/azure-sdk-assets/': Failed to connect to github.com port 443: Connection timed out + if (result.StdErr.Contains("Failed to connect to github.com port 443: Connection timed out")) + { + return true; + } + + // fatal: unable to access 'https://github.com/Azure/azure-sdk-assets/': Failed to connect to github.com port 443: Operation timed out + if (result.StdErr.Contains("Failed to connect to github.com port 443: Operation timed out")) + { + return true; + } + + // fatal: unable to access 'https://github.com/Azure/azure-sdk-assets/': Failed to connect to github.com port 443 after 21019 ms: Couldn't connect to server + var regex = new Regex(@"Failed to connect to github.com port 443 after [\d]+ ms: Couldn't connect to server"); + if (regex.IsMatch(result.StdErr)) + { + return true; + } + } + + return false; + } + /// /// Invokes git binary against a GitAssetsConfiguration. /// @@ -214,52 +280,71 @@ public virtual bool TryRun(string arguments, string workingDirectory, out Comman { try { - DebugLogger.LogInformation($"git {arguments}"); - var output = new List(); - var error = new List(); - - using (var process = new Process()) + int attempts = 1; + bool continueToAttempt = true; + while (continueToAttempt && attempts <= RETRY_INTERMITTENT_FAILURE_COUNT) { - process.StartInfo = processStartInfo; + DebugLogger.LogInformation($"git {arguments}"); + var output = new List(); + var error = new List(); - process.OutputDataReceived += (s, e) => + using (var process = new Process()) { - lock (output) - { - output.Add(e.Data); - } - }; + process.StartInfo = processStartInfo; - process.ErrorDataReceived += (s, e) => - { - lock (error) + process.OutputDataReceived += (s, e) => { - error.Add(e.Data); - } - }; + lock (output) + { + output.Add(e.Data); + } + }; - process.Start(); - process.BeginErrorReadLine(); - process.BeginOutputReadLine(); - process.WaitForExit(); - - int returnCode = process.ExitCode; - var stdOut = string.Join(Environment.NewLine, output); - var stdError = string.Join(Environment.NewLine, error); + process.ErrorDataReceived += (s, e) => + { + lock (error) + { + error.Add(e.Data); + } + }; + + process.Start(); + process.BeginErrorReadLine(); + process.BeginOutputReadLine(); + process.WaitForExit(); + + int returnCode = process.ExitCode; + var stdOut = string.Join(Environment.NewLine, output); + var stdError = string.Join(Environment.NewLine, error); + + DebugLogger.LogDebug($"StdOut: {stdOut}"); + DebugLogger.LogDebug($"StdErr: {stdError}"); + DebugLogger.LogDebug($"ExitCode: {process.ExitCode}"); + + commandResult = new CommandResult() + { + ExitCode = process.ExitCode, + StdErr = stdError, + StdOut = stdOut, + Arguments = arguments + }; - DebugLogger.LogDebug($"StdOut: {stdOut}"); - DebugLogger.LogDebug($"StdErr: {stdError}"); - DebugLogger.LogDebug($"ExitCode: {process.ExitCode}"); + if (commandResult.ExitCode == 0) + { + break; + } + continueToAttempt = IsRetriableGitError(commandResult); - commandResult = new CommandResult() - { - ExitCode = process.ExitCode, - StdErr = stdError, - StdOut = stdOut, - Arguments = arguments - }; + attempts++; + if (continueToAttempt && attempts < RETRY_INTERMITTENT_FAILURE_COUNT) + { + Task.Delay(attempts * 2 * 1000).Wait(); + } + } } } + // exceptions caught here will be to do with inability to start the git process + // otherwise all "error" states should be handled by the output to stdErr and non-zero exitcode. catch (Exception e) { DebugLogger.LogDebug(e.Message);