From caadae819b27e3aa395ba6ca9c5cc5f83368d424 Mon Sep 17 00:00:00 2001 From: Andy Zivkovic Date: Fri, 11 Nov 2022 06:49:48 +1030 Subject: [PATCH 1/4] Observe Retry-After delay on HTTP request retry --- .../NuGet.Protocol/EnhancedHttpRetryHelper.cs | 17 +++++ .../HttpSource/HttpRetryHandler.cs | 68 +++++++++++++++--- .../NuGet.Protocol/Strings.Designer.cs | 11 ++- src/NuGet.Core/NuGet.Protocol/Strings.resx | 6 ++ .../HttpRetryHandlerTests.cs | 72 ++++++++++++++++++- 5 files changed, 162 insertions(+), 12 deletions(-) diff --git a/src/NuGet.Core/NuGet.Protocol/EnhancedHttpRetryHelper.cs b/src/NuGet.Core/NuGet.Protocol/EnhancedHttpRetryHelper.cs index 1f623541488..21735005121 100644 --- a/src/NuGet.Core/NuGet.Protocol/EnhancedHttpRetryHelper.cs +++ b/src/NuGet.Core/NuGet.Protocol/EnhancedHttpRetryHelper.cs @@ -33,6 +33,11 @@ internal class EnhancedHttpRetryHelper /// public const bool DefaultRetry429 = true; + /// + /// The default value indicating whether or not to observe Retry-After headers on responses. + /// + public const bool DefaultObserveRetryAfter = true; + /// /// The environment variable used to change the delay value. /// @@ -53,6 +58,11 @@ internal class EnhancedHttpRetryHelper /// public const string Retry429EnvironmentVariableName = "NUGET_RETRY_HTTP_429"; + /// + /// The envionment variable to disable observing Retry-After responses. + /// + public const string ObserveRetryAfterEnvironmentVariableName = "NUGET_OBSERVE_RETRY_AFTER"; + private readonly IEnvironmentVariableReader _environmentVariableReader; private bool? _isEnabled = null; @@ -63,6 +73,8 @@ internal class EnhancedHttpRetryHelper private bool? _retry429 = null; + private bool? _observeRetryAfter = null; + /// /// Initializes a new instance of the class. /// @@ -93,6 +105,11 @@ public EnhancedHttpRetryHelper(IEnvironmentVariableReader environmentVariableRea /// internal bool Retry429 => _retry429 ??= GetBoolFromEnvironmentVariable(Retry429EnvironmentVariableName, defaultValue: true, _environmentVariableReader); + /// + /// Gets a value indicating whether or not to observe the Retry-After header on HTTP responses. + /// + internal bool ObserveRetryAfter => _observeRetryAfter ??= GetBoolFromEnvironmentVariable(ObserveRetryAfterEnvironmentVariableName, defaultValue: DefaultObserveRetryAfter, _environmentVariableReader); + /// /// Gets a value from the specified environment variable. /// diff --git a/src/NuGet.Core/NuGet.Protocol/HttpSource/HttpRetryHandler.cs b/src/NuGet.Core/NuGet.Protocol/HttpSource/HttpRetryHandler.cs index 8411e6c7fa7..73c9c429736 100644 --- a/src/NuGet.Core/NuGet.Protocol/HttpSource/HttpRetryHandler.cs +++ b/src/NuGet.Core/NuGet.Protocol/HttpSource/HttpRetryHandler.cs @@ -1,11 +1,14 @@ // Copyright (c) .NET Foundation. All rights reserved. // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. +#nullable enable + using System; using System.Collections.Generic; using System.Diagnostics; using System.Globalization; using System.Net.Http; +using System.Net.Http.Headers; using System.Threading; using System.Threading.Tasks; using NuGet.Common; @@ -37,10 +40,12 @@ internal HttpRetryHandler(IEnvironmentVariableReader environmentVariableReader) /// requests cannot always be used. For example, suppose the request is a POST and contains content /// of a stream that can only be consumed once. /// +#nullable disable public Task SendAsync( HttpRetryHandlerRequest request, ILogger log, CancellationToken cancellationToken) +#nullable enable { return SendAsync(request, source: string.Empty, log, cancellationToken); } @@ -53,11 +58,13 @@ public Task SendAsync( /// requests cannot always be used. For example, suppose the request is a POST and contains content /// of a stream that can only be consumed once. /// +#nullable disable public async Task SendAsync( HttpRetryHandlerRequest request, string source, ILogger log, CancellationToken cancellationToken) +#nullable enable { if (source == null) { @@ -71,8 +78,9 @@ public async Task SendAsync( } var tries = 0; - HttpResponseMessage response = null; + HttpResponseMessage? response = null; var success = false; + TimeSpan? retryAfter = null; while (tries < request.MaxTries && !success) { @@ -80,7 +88,11 @@ public async Task SendAsync( // so the Delay() never actually occurs. // When opted in to "enhanced retry", do the delay and have it increase exponentially where applicable // (i.e. when "tries" is allowed to be > 1) - if (tries > 0 || (_enhancedHttpRetryHelper.IsEnabled && request.IsRetry)) + if (retryAfter != null && _enhancedHttpRetryHelper.ObserveRetryAfter) + { + await Task.Delay(retryAfter.Value, cancellationToken); + } + else if (tries > 0 || (_enhancedHttpRetryHelper.IsEnabled && request.IsRetry)) { // "Enhanced" retry: In the case where this is actually a 2nd-Nth try, back off exponentially with some random. // In many cases due to the external retry loop, this will be always be 1 * request.RetryDelay.TotalMilliseconds + 0-200 ms @@ -107,7 +119,7 @@ public async Task SendAsync( var stopwatches = new List(2); var bodyStopwatch = new Stopwatch(); stopwatches.Add(bodyStopwatch); - Stopwatch headerStopwatch = null; + Stopwatch? headerStopwatch = null; if (request.CompletionOption == HttpCompletionOption.ResponseHeadersRead) { headerStopwatch = new Stopwatch(); @@ -118,7 +130,7 @@ public async Task SendAsync( #else requestMessage.Properties[StopwatchPropertyName] = stopwatches; #endif - var requestUri = requestMessage.RequestUri; + var requestUri = requestMessage.RequestUri!; try { @@ -197,12 +209,31 @@ public async Task SendAsync( response.Content = newContent; } - log.LogInformation(" " + string.Format( - CultureInfo.InvariantCulture, - Strings.Http_ResponseLog, - response.StatusCode, - requestUri, - bodyStopwatch.ElapsedMilliseconds)); + retryAfter = GetRetryAfter(response.Headers.RetryAfter); + if (retryAfter != null) + { + log.LogInformation(" " + string.Format( + CultureInfo.InvariantCulture, + Strings.Http_ResponseLogWithRetryAfter, + response.StatusCode, + requestUri, + bodyStopwatch.ElapsedMilliseconds, + retryAfter.Value.TotalSeconds)); + } + else + { + log.LogInformation(" " + string.Format( + CultureInfo.InvariantCulture, + Strings.Http_ResponseLog, + response.StatusCode, + requestUri, + bodyStopwatch.ElapsedMilliseconds)); + } + + if (retryAfter?.TotalMilliseconds < 0) + { + retryAfter = null; + } int statusCode = (int)response.StatusCode; // 5xx == server side failure @@ -270,5 +301,22 @@ public async Task SendAsync( return response; } + + private static TimeSpan? GetRetryAfter(RetryConditionHeaderValue? retryAfter) + { + if (retryAfter?.Delta != null) + { + return retryAfter.Delta; + } + + if (retryAfter?.Date != null) + { + DateTimeOffset retryAfterDate = retryAfter.Date.Value.ToUniversalTime(); + var now = DateTimeOffset.UtcNow; + return retryAfterDate - now; + } + + return null; + } } } diff --git a/src/NuGet.Core/NuGet.Protocol/Strings.Designer.cs b/src/NuGet.Core/NuGet.Protocol/Strings.Designer.cs index 159a6e4dff6..d288cce834c 100644 --- a/src/NuGet.Core/NuGet.Protocol/Strings.Designer.cs +++ b/src/NuGet.Core/NuGet.Protocol/Strings.Designer.cs @@ -213,6 +213,15 @@ internal static string Http_ResponseLog { } } + /// + /// Looks up a localized string similar to {0} {1} {2}ms (retry after: {3}s). + /// + internal static string Http_ResponseLogWithRetryAfter { + get { + return ResourceManager.GetString("Http_ResponseLogWithRetryAfter", resourceCulture); + } + } + /// /// Looks up a localized string similar to The HTTP request to '{0} {1}' has timed out after {2}ms.. /// @@ -961,7 +970,7 @@ internal static string UnableToParseFolderV3Version { } /// - /// Looks up a localized string similar to You are running the '{0}' operation with an 'HTTP' source, '{1}'. Non-HTTPS access will be removed in a future version. Consider migrating to 'HTTPS' sources.. + /// Looks up a localized string similar to You are running the '{0}' operation with an 'HTTP' source, '{1}'. Non-HTTPS access will be removed in a future version. Consider migrating to an 'HTTPS' source.. /// internal static string Warning_HttpServerUsage { get { diff --git a/src/NuGet.Core/NuGet.Protocol/Strings.resx b/src/NuGet.Core/NuGet.Protocol/Strings.resx index c816cb72839..786c80abfbf 100644 --- a/src/NuGet.Core/NuGet.Protocol/Strings.resx +++ b/src/NuGet.Core/NuGet.Protocol/Strings.resx @@ -482,4 +482,10 @@ The "ms" should be localized to the abbreviation for milliseconds. You are running the '{0}' operation with an 'HTTP' source, '{1}'. Non-HTTPS access will be removed in a future version. Consider migrating to an 'HTTPS' source. 0 - The command name. Ex. Push/Delete. 1 - server uri. + + {0} {1} {2}ms (retry after: {3}s) + Parameters in order: non-localizable HTTP status, non-localizable HTTP request URI, request duration in milliseconds, retry after duration in milliseconds +The "ms" should be localized to the abbreviation for milliseconds. +The "s" should be localized to the abbreviation for seconds. + \ No newline at end of file diff --git a/test/NuGet.Core.FuncTests/NuGet.Protocol.FuncTest/HttpRetryHandlerTests.cs b/test/NuGet.Core.FuncTests/NuGet.Protocol.FuncTest/HttpRetryHandlerTests.cs index bc37069a642..ffee51ed2be 100644 --- a/test/NuGet.Core.FuncTests/NuGet.Protocol.FuncTest/HttpRetryHandlerTests.cs +++ b/test/NuGet.Core.FuncTests/NuGet.Protocol.FuncTest/HttpRetryHandlerTests.cs @@ -3,10 +3,12 @@ using System; using System.Collections.Generic; +using System.Diagnostics; using System.Net; using System.Net.Http; using System.Threading; using System.Threading.Tasks; +using FluentAssertions; using NuGet.Common; using NuGet.Protocol; using NuGet.Test.Server; @@ -18,7 +20,7 @@ namespace NuGet.Core.FuncTest { public class HttpRetryHandlerTests { - private const string TestUrl = "https://test.local/test.json"; + private const string TestUrl = "https://local.test/test.json"; [Fact] public async Task HttpRetryHandler_ReturnsContentHeaders() @@ -176,6 +178,59 @@ public async Task HttpRetryHandler_HandlesNameResolutionFailure() #endif } + [Fact] + public async Task HttpRetryHandler_429WithRetryAfterHeader_UsesHeaderDelay() + { + // Arrange + int attempt = 0; + // .NET Framework don't have HttpStatusCode.TooManyRequests + HttpStatusCode tooManyRequestsStatusCode = (HttpStatusCode)429; + + var busyServer = new HttpRetryTestHandler((req, cancellationToken) => + { + if (attempt++ < 2) + { + var response = new HttpResponseMessage(tooManyRequestsStatusCode); + response.Headers.RetryAfter = new System.Net.Http.Headers.RetryConditionHeaderValue(TimeSpan.FromMilliseconds(1)); + return Task.FromResult(response); + } + else + { + return Task.FromResult(new HttpResponseMessage(HttpStatusCode.OK)); + } + }); + var client = new HttpClient(busyServer); + + // Use a very long timeout that will tell us that Retry-After wasn't being used. + TimeSpan retryDelay = TimeSpan.FromHours(5); + var httpRetryHandlerRequest = new HttpRetryHandlerRequest(client, () => new HttpRequestMessage(HttpMethod.Get, TestUrl)) + { + RetryDelay = retryDelay + }; + TestEnvironmentVariableReader environmentVariables = GetEnhancedHttpRetryEnvironmentVariables(retry429: true, observeRetryAfter: true, delayMilliseconds: (int)retryDelay.TotalMilliseconds); + var httpRetryHandler = new HttpRetryHandler(environmentVariables); + var logger = new TestLogger(); + + // Act + HttpResponseMessage response; + int cancellationDelay = Debugger.IsAttached ? int.MaxValue : 1000; + using (var cts = new CancellationTokenSource(millisecondsDelay: cancellationDelay)) + { + try + { + response = await httpRetryHandler.SendAsync(httpRetryHandlerRequest, logger, cts.Token); + } + catch (OperationCanceledException) when (cts.Token.IsCancellationRequested) + { + throw new Exception("HTTP response Retry-After not used"); + } + } + + // Assert + response.StatusCode.Should().Be(HttpStatusCode.OK); + attempt.Should().Be(3); + } + private static async Task ThrowsException(ITestServer server) where T : Exception { return await server.ExecuteAsync(async address => @@ -213,6 +268,21 @@ private static async Task ThrowsException(ITestServer server) where T : Ex }); } + private static TestEnvironmentVariableReader GetEnhancedHttpRetryEnvironmentVariables( + bool? isEnabled = true, + int? retryCount = 5, + int? delayMilliseconds = 0, + bool? retry429 = true, + bool? observeRetryAfter = true) + => new TestEnvironmentVariableReader( + new Dictionary() + { + [EnhancedHttpRetryHelper.IsEnabledEnvironmentVariableName] = isEnabled?.ToString(), + [EnhancedHttpRetryHelper.RetryCountEnvironmentVariableName] = retryCount?.ToString(), + [EnhancedHttpRetryHelper.DelayInMillisecondsEnvironmentVariableName] = delayMilliseconds?.ToString(), + [EnhancedHttpRetryHelper.Retry429EnvironmentVariableName] = retry429?.ToString(), + }); + private class CountingHandler : DelegatingHandler { public int Hits { get; private set; } From 5412d524af4f872d27b45d7b1ef26b7571a1d0bc Mon Sep 17 00:00:00 2001 From: Andy Zivkovic Date: Sat, 12 Nov 2022 09:54:35 +1030 Subject: [PATCH 2/4] Fully enable nullable checks on HttpRetryHandler --- .../HttpSource/HttpRetryHandler.cs | 21 ++++++++----------- .../PublicAPI/net472/PublicAPI.Shipped.txt | 4 ++-- .../netcoreapp5.0/PublicAPI.Shipped.txt | 4 ++-- .../netstandard2.0/PublicAPI.Shipped.txt | 4 ++-- 4 files changed, 15 insertions(+), 18 deletions(-) diff --git a/src/NuGet.Core/NuGet.Protocol/HttpSource/HttpRetryHandler.cs b/src/NuGet.Core/NuGet.Protocol/HttpSource/HttpRetryHandler.cs index 73c9c429736..66e1ab8a032 100644 --- a/src/NuGet.Core/NuGet.Protocol/HttpSource/HttpRetryHandler.cs +++ b/src/NuGet.Core/NuGet.Protocol/HttpSource/HttpRetryHandler.cs @@ -40,12 +40,10 @@ internal HttpRetryHandler(IEnvironmentVariableReader environmentVariableReader) /// requests cannot always be used. For example, suppose the request is a POST and contains content /// of a stream that can only be consumed once. /// -#nullable disable public Task SendAsync( HttpRetryHandlerRequest request, ILogger log, CancellationToken cancellationToken) -#nullable enable { return SendAsync(request, source: string.Empty, log, cancellationToken); } @@ -58,13 +56,11 @@ public Task SendAsync( /// requests cannot always be used. For example, suppose the request is a POST and contains content /// of a stream that can only be consumed once. /// -#nullable disable public async Task SendAsync( HttpRetryHandlerRequest request, string source, ILogger log, CancellationToken cancellationToken) -#nullable enable { if (source == null) { @@ -79,10 +75,9 @@ public async Task SendAsync( var tries = 0; HttpResponseMessage? response = null; - var success = false; TimeSpan? retryAfter = null; - while (tries < request.MaxTries && !success) + while (true) { // There are many places where another variable named "MaxTries" is set to 1, // so the Delay() never actually occurs. @@ -112,7 +107,6 @@ public async Task SendAsync( } tries++; - success = true; using (var requestMessage = request.RequestFactory()) { @@ -241,7 +235,14 @@ public async Task SendAsync( // 429 == too many requests if (statusCode >= 500 || ((statusCode == 408 || statusCode == 429) && _enhancedHttpRetryHelper.Retry429)) { - success = false; + if (tries == request.MaxTries) + { + return response; + } + } + else + { + return response; } } catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested) @@ -265,8 +266,6 @@ public async Task SendAsync( } catch (Exception e) { - success = false; - response?.Dispose(); ProtocolDiagnostics.RaiseEvent(new ProtocolDiagnosticHttpEvent( @@ -298,8 +297,6 @@ public async Task SendAsync( } } } - - return response; } private static TimeSpan? GetRetryAfter(RetryConditionHeaderValue? retryAfter) diff --git a/src/NuGet.Core/NuGet.Protocol/PublicAPI/net472/PublicAPI.Shipped.txt b/src/NuGet.Core/NuGet.Protocol/PublicAPI/net472/PublicAPI.Shipped.txt index 202554c537a..c1ddedfa620 100644 --- a/src/NuGet.Core/NuGet.Protocol/PublicAPI/net472/PublicAPI.Shipped.txt +++ b/src/NuGet.Core/NuGet.Protocol/PublicAPI/net472/PublicAPI.Shipped.txt @@ -459,8 +459,8 @@ NuGet.Protocol.HttpRequestMessageFactory NuGet.Protocol.HttpResponseMessageExtensions NuGet.Protocol.HttpRetryHandler NuGet.Protocol.HttpRetryHandler.HttpRetryHandler() -> void -~NuGet.Protocol.HttpRetryHandler.SendAsync(NuGet.Protocol.HttpRetryHandlerRequest request, NuGet.Common.ILogger log, System.Threading.CancellationToken cancellationToken) -> System.Threading.Tasks.Task -~NuGet.Protocol.HttpRetryHandler.SendAsync(NuGet.Protocol.HttpRetryHandlerRequest request, string source, NuGet.Common.ILogger log, System.Threading.CancellationToken cancellationToken) -> System.Threading.Tasks.Task +NuGet.Protocol.HttpRetryHandler.SendAsync(NuGet.Protocol.HttpRetryHandlerRequest! request, NuGet.Common.ILogger! log, System.Threading.CancellationToken cancellationToken) -> System.Threading.Tasks.Task! +NuGet.Protocol.HttpRetryHandler.SendAsync(NuGet.Protocol.HttpRetryHandlerRequest! request, string! source, NuGet.Common.ILogger! log, System.Threading.CancellationToken cancellationToken) -> System.Threading.Tasks.Task! NuGet.Protocol.HttpRetryHandlerRequest ~NuGet.Protocol.HttpRetryHandlerRequest.AddHeaders.get -> System.Collections.Generic.IList>> ~NuGet.Protocol.HttpRetryHandlerRequest.AddHeaders.set -> void diff --git a/src/NuGet.Core/NuGet.Protocol/PublicAPI/netcoreapp5.0/PublicAPI.Shipped.txt b/src/NuGet.Core/NuGet.Protocol/PublicAPI/netcoreapp5.0/PublicAPI.Shipped.txt index eda2e615767..dbda1334216 100644 --- a/src/NuGet.Core/NuGet.Protocol/PublicAPI/netcoreapp5.0/PublicAPI.Shipped.txt +++ b/src/NuGet.Core/NuGet.Protocol/PublicAPI/netcoreapp5.0/PublicAPI.Shipped.txt @@ -459,8 +459,8 @@ NuGet.Protocol.HttpRequestMessageFactory NuGet.Protocol.HttpResponseMessageExtensions NuGet.Protocol.HttpRetryHandler NuGet.Protocol.HttpRetryHandler.HttpRetryHandler() -> void -~NuGet.Protocol.HttpRetryHandler.SendAsync(NuGet.Protocol.HttpRetryHandlerRequest request, NuGet.Common.ILogger log, System.Threading.CancellationToken cancellationToken) -> System.Threading.Tasks.Task -~NuGet.Protocol.HttpRetryHandler.SendAsync(NuGet.Protocol.HttpRetryHandlerRequest request, string source, NuGet.Common.ILogger log, System.Threading.CancellationToken cancellationToken) -> System.Threading.Tasks.Task +NuGet.Protocol.HttpRetryHandler.SendAsync(NuGet.Protocol.HttpRetryHandlerRequest! request, NuGet.Common.ILogger! log, System.Threading.CancellationToken cancellationToken) -> System.Threading.Tasks.Task! +NuGet.Protocol.HttpRetryHandler.SendAsync(NuGet.Protocol.HttpRetryHandlerRequest! request, string! source, NuGet.Common.ILogger! log, System.Threading.CancellationToken cancellationToken) -> System.Threading.Tasks.Task! NuGet.Protocol.HttpRetryHandlerRequest ~NuGet.Protocol.HttpRetryHandlerRequest.AddHeaders.get -> System.Collections.Generic.IList>> ~NuGet.Protocol.HttpRetryHandlerRequest.AddHeaders.set -> void diff --git a/src/NuGet.Core/NuGet.Protocol/PublicAPI/netstandard2.0/PublicAPI.Shipped.txt b/src/NuGet.Core/NuGet.Protocol/PublicAPI/netstandard2.0/PublicAPI.Shipped.txt index eda2e615767..dbda1334216 100644 --- a/src/NuGet.Core/NuGet.Protocol/PublicAPI/netstandard2.0/PublicAPI.Shipped.txt +++ b/src/NuGet.Core/NuGet.Protocol/PublicAPI/netstandard2.0/PublicAPI.Shipped.txt @@ -459,8 +459,8 @@ NuGet.Protocol.HttpRequestMessageFactory NuGet.Protocol.HttpResponseMessageExtensions NuGet.Protocol.HttpRetryHandler NuGet.Protocol.HttpRetryHandler.HttpRetryHandler() -> void -~NuGet.Protocol.HttpRetryHandler.SendAsync(NuGet.Protocol.HttpRetryHandlerRequest request, NuGet.Common.ILogger log, System.Threading.CancellationToken cancellationToken) -> System.Threading.Tasks.Task -~NuGet.Protocol.HttpRetryHandler.SendAsync(NuGet.Protocol.HttpRetryHandlerRequest request, string source, NuGet.Common.ILogger log, System.Threading.CancellationToken cancellationToken) -> System.Threading.Tasks.Task +NuGet.Protocol.HttpRetryHandler.SendAsync(NuGet.Protocol.HttpRetryHandlerRequest! request, NuGet.Common.ILogger! log, System.Threading.CancellationToken cancellationToken) -> System.Threading.Tasks.Task! +NuGet.Protocol.HttpRetryHandler.SendAsync(NuGet.Protocol.HttpRetryHandlerRequest! request, string! source, NuGet.Common.ILogger! log, System.Threading.CancellationToken cancellationToken) -> System.Threading.Tasks.Task! NuGet.Protocol.HttpRetryHandlerRequest ~NuGet.Protocol.HttpRetryHandlerRequest.AddHeaders.get -> System.Collections.Generic.IList>> ~NuGet.Protocol.HttpRetryHandlerRequest.AddHeaders.set -> void From 27fb4f110be196be4477310a037cd206d01571e2 Mon Sep 17 00:00:00 2001 From: Andy Zivkovic Date: Sat, 12 Nov 2022 10:34:01 +1030 Subject: [PATCH 3/4] Add env var to cap maximum Retry-After delay --- .../NuGet.Protocol/EnhancedHttpRetryHelper.cs | 26 +++++++++ .../HttpSource/HttpRetryHandler.cs | 14 +++-- .../HttpRetryHandlerTests.cs | 56 ++++++++++++++++++- 3 files changed, 89 insertions(+), 7 deletions(-) diff --git a/src/NuGet.Core/NuGet.Protocol/EnhancedHttpRetryHelper.cs b/src/NuGet.Core/NuGet.Protocol/EnhancedHttpRetryHelper.cs index 21735005121..fac04e0e2eb 100644 --- a/src/NuGet.Core/NuGet.Protocol/EnhancedHttpRetryHelper.cs +++ b/src/NuGet.Core/NuGet.Protocol/EnhancedHttpRetryHelper.cs @@ -63,6 +63,11 @@ internal class EnhancedHttpRetryHelper /// public const string ObserveRetryAfterEnvironmentVariableName = "NUGET_OBSERVE_RETRY_AFTER"; + /// + /// The environment variable used to set maximum Retry-After delay period + /// + public const string MaximumRetryAfterDurationEnvironmentVariableName = "NUGET_MAX_RETRY_AFTER_DELAY_SECONDS"; + private readonly IEnvironmentVariableReader _environmentVariableReader; private bool? _isEnabled = null; @@ -75,6 +80,9 @@ internal class EnhancedHttpRetryHelper private bool? _observeRetryAfter = null; + private TimeSpan? _maxRetyAfterDelay = null; + private bool _gotMaxRetryAfterDelay = false; + /// /// Initializes a new instance of the class. /// @@ -110,6 +118,24 @@ public EnhancedHttpRetryHelper(IEnvironmentVariableReader environmentVariableRea /// internal bool ObserveRetryAfter => _observeRetryAfter ??= GetBoolFromEnvironmentVariable(ObserveRetryAfterEnvironmentVariableName, defaultValue: DefaultObserveRetryAfter, _environmentVariableReader); + internal TimeSpan? MaxRetryAfterDelay + { + get + { + if (!_gotMaxRetryAfterDelay) + { + if (int.TryParse(_environmentVariableReader.GetEnvironmentVariable(MaximumRetryAfterDurationEnvironmentVariableName), out int maxRetryAfterDelay)) + { + _maxRetyAfterDelay = TimeSpan.FromSeconds(maxRetryAfterDelay); + } + + _gotMaxRetryAfterDelay = true; + } + + return _maxRetyAfterDelay; + } + } + /// /// Gets a value from the specified environment variable. /// diff --git a/src/NuGet.Core/NuGet.Protocol/HttpSource/HttpRetryHandler.cs b/src/NuGet.Core/NuGet.Protocol/HttpSource/HttpRetryHandler.cs index 66e1ab8a032..91bbe536ae3 100644 --- a/src/NuGet.Core/NuGet.Protocol/HttpSource/HttpRetryHandler.cs +++ b/src/NuGet.Core/NuGet.Protocol/HttpSource/HttpRetryHandler.cs @@ -213,6 +213,15 @@ public async Task SendAsync( requestUri, bodyStopwatch.ElapsedMilliseconds, retryAfter.Value.TotalSeconds)); + + if (retryAfter.Value.TotalMilliseconds < 0) + { + retryAfter = null; + } + else if (retryAfter.Value > _enhancedHttpRetryHelper.MaxRetryAfterDelay) + { + retryAfter = _enhancedHttpRetryHelper.MaxRetryAfterDelay; + } } else { @@ -224,11 +233,6 @@ public async Task SendAsync( bodyStopwatch.ElapsedMilliseconds)); } - if (retryAfter?.TotalMilliseconds < 0) - { - retryAfter = null; - } - int statusCode = (int)response.StatusCode; // 5xx == server side failure // 408 == request timeout diff --git a/test/NuGet.Core.FuncTests/NuGet.Protocol.FuncTest/HttpRetryHandlerTests.cs b/test/NuGet.Core.FuncTests/NuGet.Protocol.FuncTest/HttpRetryHandlerTests.cs index ffee51ed2be..30fb6ba5068 100644 --- a/test/NuGet.Core.FuncTests/NuGet.Protocol.FuncTest/HttpRetryHandlerTests.cs +++ b/test/NuGet.Core.FuncTests/NuGet.Protocol.FuncTest/HttpRetryHandlerTests.cs @@ -213,7 +213,7 @@ public async Task HttpRetryHandler_429WithRetryAfterHeader_UsesHeaderDelay() // Act HttpResponseMessage response; - int cancellationDelay = Debugger.IsAttached ? int.MaxValue : 1000; + int cancellationDelay = Debugger.IsAttached ? int.MaxValue : 60 * 1000; using (var cts = new CancellationTokenSource(millisecondsDelay: cancellationDelay)) { try @@ -231,6 +231,55 @@ public async Task HttpRetryHandler_429WithRetryAfterHeader_UsesHeaderDelay() attempt.Should().Be(3); } + [Fact] + public async Task HttpRetryHandler_LongRetryAfterDuration_UsesEnvVarSetting() + { + // Arrange + int attempts = 0; + // .NET Framework don't have HttpStatusCode.TooManyRequests + HttpStatusCode tooManyRequestsStatusCode = (HttpStatusCode)429; + + var busyServer = new HttpRetryTestHandler((req, cancellationToken) => + { + attempts++; + var response = new HttpResponseMessage(tooManyRequestsStatusCode); + response.Headers.RetryAfter = new System.Net.Http.Headers.RetryConditionHeaderValue(TimeSpan.FromHours(1)); + return Task.FromResult(response); + }); + var client = new HttpClient(busyServer); + + // Use a very long timeout that will tell us that Retry-After wasn't being used. + TimeSpan retryDelay = TimeSpan.FromHours(1); + var httpRetryHandlerRequest = new HttpRetryHandlerRequest(client, () => new HttpRequestMessage(HttpMethod.Get, TestUrl)) + { + MaxTries = 2, + RetryDelay = retryDelay + }; + TestEnvironmentVariableReader environmentVariables = + GetEnhancedHttpRetryEnvironmentVariables(retryCount: 2, retry429: true, observeRetryAfter: true, delayMilliseconds: (int)retryDelay.TotalMilliseconds, maxRetryAfterSeconds: 1); + var httpRetryHandler = new HttpRetryHandler(environmentVariables); + var logger = new TestLogger(); + + // Act + HttpResponseMessage response; + int cancellationDelay = Debugger.IsAttached ? int.MaxValue : 60 * 1000; + using (var cts = new CancellationTokenSource(millisecondsDelay: cancellationDelay)) + { + try + { + response = await httpRetryHandler.SendAsync(httpRetryHandlerRequest, logger, cts.Token); + } + catch (OperationCanceledException) when (cts.Token.IsCancellationRequested) + { + throw new Exception("HTTP response Retry-After not used"); + } + } + + // Assert + response.StatusCode.Should().Be(tooManyRequestsStatusCode); + attempts.Should().Be(2); + } + private static async Task ThrowsException(ITestServer server) where T : Exception { return await server.ExecuteAsync(async address => @@ -273,7 +322,8 @@ private static TestEnvironmentVariableReader GetEnhancedHttpRetryEnvironmentVari int? retryCount = 5, int? delayMilliseconds = 0, bool? retry429 = true, - bool? observeRetryAfter = true) + bool? observeRetryAfter = true, + int? maxRetryAfterSeconds = null) => new TestEnvironmentVariableReader( new Dictionary() { @@ -281,6 +331,8 @@ private static TestEnvironmentVariableReader GetEnhancedHttpRetryEnvironmentVari [EnhancedHttpRetryHelper.RetryCountEnvironmentVariableName] = retryCount?.ToString(), [EnhancedHttpRetryHelper.DelayInMillisecondsEnvironmentVariableName] = delayMilliseconds?.ToString(), [EnhancedHttpRetryHelper.Retry429EnvironmentVariableName] = retry429?.ToString(), + [EnhancedHttpRetryHelper.ObserveRetryAfterEnvironmentVariableName] = observeRetryAfter?.ToString(), + [EnhancedHttpRetryHelper.MaximumRetryAfterDurationEnvironmentVariableName] = maxRetryAfterSeconds?.ToString(), }); private class CountingHandler : DelegatingHandler From 71478f9a94940cfd8636d767ebfb38071bb842c7 Mon Sep 17 00:00:00 2001 From: Andy Zivkovic Date: Tue, 15 Nov 2022 10:34:28 +1030 Subject: [PATCH 4/4] feedback --- .../NuGet.Protocol/EnhancedHttpRetryHelper.cs | 15 +++++---------- .../HttpRetryHandlerTests.cs | 18 ++++++------------ 2 files changed, 11 insertions(+), 22 deletions(-) diff --git a/src/NuGet.Core/NuGet.Protocol/EnhancedHttpRetryHelper.cs b/src/NuGet.Core/NuGet.Protocol/EnhancedHttpRetryHelper.cs index fac04e0e2eb..1883463bc5e 100644 --- a/src/NuGet.Core/NuGet.Protocol/EnhancedHttpRetryHelper.cs +++ b/src/NuGet.Core/NuGet.Protocol/EnhancedHttpRetryHelper.cs @@ -81,7 +81,6 @@ internal class EnhancedHttpRetryHelper private bool? _observeRetryAfter = null; private TimeSpan? _maxRetyAfterDelay = null; - private bool _gotMaxRetryAfterDelay = false; /// /// Initializes a new instance of the class. @@ -118,21 +117,17 @@ public EnhancedHttpRetryHelper(IEnvironmentVariableReader environmentVariableRea /// internal bool ObserveRetryAfter => _observeRetryAfter ??= GetBoolFromEnvironmentVariable(ObserveRetryAfterEnvironmentVariableName, defaultValue: DefaultObserveRetryAfter, _environmentVariableReader); - internal TimeSpan? MaxRetryAfterDelay + internal TimeSpan MaxRetryAfterDelay { get { - if (!_gotMaxRetryAfterDelay) + if (_maxRetyAfterDelay == null) { - if (int.TryParse(_environmentVariableReader.GetEnvironmentVariable(MaximumRetryAfterDurationEnvironmentVariableName), out int maxRetryAfterDelay)) - { - _maxRetyAfterDelay = TimeSpan.FromSeconds(maxRetryAfterDelay); - } - - _gotMaxRetryAfterDelay = true; + int maxRetryAfterDelay = GetIntFromEnvironmentVariable(MaximumRetryAfterDurationEnvironmentVariableName, defaultValue: (int)TimeSpan.FromHours(1).TotalSeconds, _environmentVariableReader); + _maxRetyAfterDelay = TimeSpan.FromSeconds(maxRetryAfterDelay); } - return _maxRetyAfterDelay; + return _maxRetyAfterDelay.Value; } } diff --git a/test/NuGet.Core.FuncTests/NuGet.Protocol.FuncTest/HttpRetryHandlerTests.cs b/test/NuGet.Core.FuncTests/NuGet.Protocol.FuncTest/HttpRetryHandlerTests.cs index 30fb6ba5068..bfaaf4b2db9 100644 --- a/test/NuGet.Core.FuncTests/NuGet.Protocol.FuncTest/HttpRetryHandlerTests.cs +++ b/test/NuGet.Core.FuncTests/NuGet.Protocol.FuncTest/HttpRetryHandlerTests.cs @@ -179,7 +179,7 @@ public async Task HttpRetryHandler_HandlesNameResolutionFailure() } [Fact] - public async Task HttpRetryHandler_429WithRetryAfterHeader_UsesHeaderDelay() + public async Task HttpRetryHandler_429WithRetryAfterHeader_UsesRetryAfterValue() { // Arrange int attempt = 0; @@ -188,16 +188,10 @@ public async Task HttpRetryHandler_429WithRetryAfterHeader_UsesHeaderDelay() var busyServer = new HttpRetryTestHandler((req, cancellationToken) => { - if (attempt++ < 2) - { - var response = new HttpResponseMessage(tooManyRequestsStatusCode); - response.Headers.RetryAfter = new System.Net.Http.Headers.RetryConditionHeaderValue(TimeSpan.FromMilliseconds(1)); - return Task.FromResult(response); - } - else - { - return Task.FromResult(new HttpResponseMessage(HttpStatusCode.OK)); - } + attempt++; + var response = new HttpResponseMessage(tooManyRequestsStatusCode); + response.Headers.RetryAfter = new System.Net.Http.Headers.RetryConditionHeaderValue(TimeSpan.FromMilliseconds(1)); + return Task.FromResult(response); }); var client = new HttpClient(busyServer); @@ -227,7 +221,7 @@ public async Task HttpRetryHandler_429WithRetryAfterHeader_UsesHeaderDelay() } // Assert - response.StatusCode.Should().Be(HttpStatusCode.OK); + response.StatusCode.Should().Be(tooManyRequestsStatusCode); attempt.Should().Be(3); }