diff --git a/source/Halibut.Tests/BaseTest.cs b/source/Halibut.Tests/BaseTest.cs index 1ae8d199..05685301 100644 --- a/source/Halibut.Tests/BaseTest.cs +++ b/source/Halibut.Tests/BaseTest.cs @@ -24,7 +24,8 @@ public class BaseTest [SetUp] public void SetUp() { - traceLogFileLogger = new TraceLogFileLogger(SerilogLoggerBuilder.CurrentTestHash()); + var isRetry = TestContext.CurrentContext.CurrentRepeatCount > 0; + traceLogFileLogger = new TraceLogFileLogger(SerilogLoggerBuilder.CurrentTestHash(), appendToExisting: isRetry); Logger = new SerilogLoggerBuilder() .SetTraceLogFileLogger(traceLogFileLogger) .Build() @@ -34,7 +35,7 @@ public void SetUp() Logger.Information("Trace log file {LogFile}", traceLogFileLogger.logFilePath); - Logger.Information("Test started"); + Logger.Information(isRetry ? $"Test started (retry {TestContext.CurrentContext.CurrentRepeatCount})" : "Test started"); cancellationTokenSource = new CancellationTokenSource(); CancellationToken = cancellationTokenSource.Token; } diff --git a/source/Halibut.Tests/Support/SerilogLoggerBuilder.cs b/source/Halibut.Tests/Support/SerilogLoggerBuilder.cs index 14220c47..9312ae81 100644 --- a/source/Halibut.Tests/Support/SerilogLoggerBuilder.cs +++ b/source/Halibut.Tests/Support/SerilogLoggerBuilder.cs @@ -65,7 +65,10 @@ public ILogger Build() if (traceFileLogger != null) { - TraceLoggers.AddOrUpdate(testName, traceFileLogger, (_, _) => throw new Exception("This should never be updated. If it is, it means that a test is being run multiple times in a single test run")); + // A retried test (see RetryOnTransportTimeoutAttribute) legitimately replaces the logger from its previous attempt. + TraceLoggers.AddOrUpdate(testName, traceFileLogger, (_, _) => TestContext.CurrentContext.CurrentRepeatCount > 0 + ? traceFileLogger + : throw new Exception("This should never be updated. If it is, it means that a test is being run multiple times in a single test run")); } return logger; diff --git a/source/Halibut.Tests/Support/TestAttributes/RetryOnTransportTimeoutAttribute.cs b/source/Halibut.Tests/Support/TestAttributes/RetryOnTransportTimeoutAttribute.cs new file mode 100644 index 00000000..4b36ba4b --- /dev/null +++ b/source/Halibut.Tests/Support/TestAttributes/RetryOnTransportTimeoutAttribute.cs @@ -0,0 +1,144 @@ +using System; +using System.Runtime.CompilerServices; +using NUnit.Framework; +using NUnit.Framework.Interfaces; +using NUnit.Framework.Internal; +using NUnit.Framework.Internal.Commands; + +namespace Halibut.Tests.Support.TestAttributes +{ + /// + /// Retries a test only when it fails with a transport read timeout (see ). + /// Any other failure (assertion, protocol error, unexpected exception) fails immediately, as before. + /// + /// By default this only applies on .NET Framework, where LEV-2253 shows intermittent read timeouts + /// blocking the nightly build chain. Every retry is reported (test output, and a TeamCity build tag and + /// warning when running under TeamCity) so the underlying problem stays visible while it is investigated. + /// + /// NUnit's built-in [Retry] cannot be used: it only retries assertion failures, not exceptions. + /// + [AttributeUsage(AttributeTargets.Method, AllowMultiple = false, Inherited = false)] + public class RetryOnTransportTimeoutAttribute : NUnitAttribute, IRepeatTest, IWrapTestMethod + { + public const string TeamCityBuildTag = "halibut-transport-timeout-retry"; + + static readonly ConditionalWeakTable LastExceptionByTest = new(); + + readonly int tryCount; + readonly bool netFrameworkOnly; + + /// Total number of attempts, including the first. + /// When true, tests run once (no retries) on modern .NET. + public RetryOnTransportTimeoutAttribute(int tryCount = 3, bool netFrameworkOnly = true) + { + if (tryCount < 1) throw new ArgumentOutOfRangeException(nameof(tryCount), "Must be at least 1"); + this.tryCount = tryCount; + this.netFrameworkOnly = netFrameworkOnly; + } + + static bool IsNetFramework => +#if NETFRAMEWORK + true; +#else + false; +#endif + + public TestCommand Wrap(TestCommand command) + { + // Called for both IWrapTestMethod (innermost, around the test method) and IRepeatTest (outermost, around SetUp/TearDown). + return command is TestMethodCommand + ? new CaptureExceptionCommand(command) + : new RetryCommand(command, netFrameworkOnly && !IsNetFramework ? 1 : tryCount); + } + + class ExceptionHolder + { + public Exception? Exception; + } + + static ExceptionHolder HolderFor(Test test) => LastExceptionByTest.GetValue(test, _ => new ExceptionHolder()); + + class CaptureExceptionCommand : DelegatingTestCommand + { + public CaptureExceptionCommand(TestCommand innerCommand) : base(innerCommand) + { + } + + public override TestResult Execute(TestExecutionContext context) + { + try + { + return innerCommand.Execute(context); + } + catch (Exception ex) + { + HolderFor(context.CurrentTest).Exception = ex; + throw; + } + } + } + + class RetryCommand : DelegatingTestCommand + { + readonly int tryCount; + + public RetryCommand(TestCommand innerCommand, int tryCount) : base(innerCommand) + { + this.tryCount = tryCount; + } + + public override TestResult Execute(TestExecutionContext context) + { + var holder = HolderFor(context.CurrentTest); + + for (var attempt = 1; ; attempt++) + { + holder.Exception = null; + + try + { + context.CurrentResult = innerCommand.Execute(context); + } + catch (Exception ex) + { + context.CurrentResult ??= context.CurrentTest.MakeTestResult(); + context.CurrentResult.RecordException(ex); + holder.Exception ??= ex; + } + + var failed = context.CurrentResult.ResultState.Status == TestStatus.Failed; + if (!failed || attempt >= tryCount || !TransportTimeoutClassifier.IsTransportTimeout(holder.Exception)) + { + return context.CurrentResult; + } + + ReportRetry(context, attempt, holder.Exception!); + + context.CurrentResult = context.CurrentTest.MakeTestResult(); + context.CurrentRepeatCount++; + } + } + + void ReportRetry(TestExecutionContext context, int attempt, Exception exception) + { + var message = $"LEV-2253: {context.CurrentTest.FullName} failed with a transport timeout on attempt {attempt} of {tryCount}; retrying. {exception.GetBaseException().GetType().Name}: {exception.GetBaseException().Message}"; + + TestContext.Progress.WriteLine(message); + + if (TeamCityDetection.IsRunningInTeamCity()) + { + TestContext.Progress.WriteLine($"##teamcity[addBuildTag '{TeamCityBuildTag}']"); + TestContext.Progress.WriteLine($"##teamcity[message text='{EscapeForTeamCity(message)}' status='WARNING']"); + } + } + + static string EscapeForTeamCity(string value) => + value.Replace("|", "||") + .Replace("'", "|'") + .Replace("\n", "|n") + .Replace("\r", "|r") + .Replace("[", "|[") + .Replace("]", "|]"); + } + } +} diff --git a/source/Halibut.Tests/Support/TestAttributes/RetryOnTransportTimeoutAttributeFixture.cs b/source/Halibut.Tests/Support/TestAttributes/RetryOnTransportTimeoutAttributeFixture.cs new file mode 100644 index 00000000..b3df713b --- /dev/null +++ b/source/Halibut.Tests/Support/TestAttributes/RetryOnTransportTimeoutAttributeFixture.cs @@ -0,0 +1,43 @@ +using System.Collections.Concurrent; +using System.IO; +using System.Net.Sockets; +using System.Threading.Tasks; +using FluentAssertions; +using NUnit.Framework; + +namespace Halibut.Tests.Support.TestAttributes +{ + public class RetryOnTransportTimeoutAttributeFixture : BaseTest + { + static readonly ConcurrentDictionary Attempts = new(); + + static int NextAttempt(string name) => Attempts.AddOrUpdate(name, 1, (_, n) => n + 1); + + [Test] + [RetryOnTransportTimeout(tryCount: 3, netFrameworkOnly: false)] + public async Task ATestThatTimesOutOnceThenPasses_IsRetriedAndPasses() + { + await Task.Yield(); + + var attempt = NextAttempt(nameof(ATestThatTimesOutOnceThenPasses_IsRetriedAndPasses)); + if (attempt == 1) + { + throw new HalibutClientException("An error occurred when sending a request", + new IOException("Unable to read data from the transport connection", + new SocketException((int)SocketError.TimedOut))); + } + + attempt.Should().Be(2, "the first attempt failed with a transport timeout and should be retried exactly once"); + } + + [Test] + [RetryOnTransportTimeout(tryCount: 3, netFrameworkOnly: false)] + public void SetUpRunsAgainForEachAttempt() + { + var attempt = NextAttempt(nameof(SetUpRunsAgainForEachAttempt)); + + CancellationToken.IsCancellationRequested.Should().BeFalse("BaseTest.SetUp should give each attempt a fresh token"); + if (attempt == 1) throw new SocketException((int)SocketError.TimedOut); + } + } +} diff --git a/source/Halibut.Tests/Support/TransportTimeoutClassifier.cs b/source/Halibut.Tests/Support/TransportTimeoutClassifier.cs new file mode 100644 index 00000000..f59a4148 --- /dev/null +++ b/source/Halibut.Tests/Support/TransportTimeoutClassifier.cs @@ -0,0 +1,68 @@ +using System; +using System.Collections.Generic; +using System.Net.Sockets; + +namespace Halibut.Tests.Support +{ + /// + /// Recognises the narrow class of transport timeouts tracked in LEV-2253: a connection that was + /// established (and usually authenticated) and then stopped responding mid-exchange. + /// + /// This is deliberately much narrower than : + /// connection refused, resets, protocol errors, certificate problems and assertion failures are NOT matched. + /// + public static class TransportTimeoutClassifier + { + static readonly string[] TimeoutMessages = + { + // net48 SocketError.TimedOut (10060), surfaced through IOException / HalibutClientException messages + "connected party did not properly respond after a period of time", + "connected host has failed to respond", + // Linux / macOS + "Operation timed out", + "Connection timed out", + // Polling (incl. WebSocket) pickup timeout, the symptom when the polling connection hangs (LEV-2246) + "did not collect the request within the allowed time", + }; + + public static bool IsTransportTimeout(Exception? exception) + { + foreach (var e in Flatten(exception)) + { + if (e is SocketException socketException && socketException.SocketErrorCode == SocketError.TimedOut) + { + return true; + } + + foreach (var message in TimeoutMessages) + { + if (e.Message.IndexOf(message, StringComparison.OrdinalIgnoreCase) >= 0) + { + return true; + } + } + } + + return false; + } + + static IEnumerable Flatten(Exception? exception) + { + if (exception == null) yield break; + + yield return exception; + + if (exception is AggregateException aggregateException) + { + foreach (var inner in aggregateException.InnerExceptions) + { + foreach (var e in Flatten(inner)) yield return e; + } + } + else + { + foreach (var e in Flatten(exception.InnerException)) yield return e; + } + } + } +} diff --git a/source/Halibut.Tests/TraceLogFileLogger.cs b/source/Halibut.Tests/TraceLogFileLogger.cs index e34b83cf..8a0dcf82 100644 --- a/source/Halibut.Tests/TraceLogFileLogger.cs +++ b/source/Halibut.Tests/TraceLogFileLogger.cs @@ -18,11 +18,12 @@ public class TraceLogFileLogger : IAsyncDisposable readonly CancellationTokenSource cancellationTokenSource = new CancellationTokenSource(); readonly Task writeDataToDiskTask; - public TraceLogFileLogger(string testHash) + /// True when a test is being retried (see RetryOnTransportTimeoutAttribute), so the earlier attempt's log is kept. + public TraceLogFileLogger(string testHash, bool appendToExisting = false) { this.testHash = testHash; this.logFilePath = LogFilePath(testHash); - File.Delete(logFilePath); + if (!appendToExisting) File.Delete(logFilePath); writeDataToDiskTask = WriteDataToFile(); } diff --git a/source/Halibut.Tests/UsageFixture.cs b/source/Halibut.Tests/UsageFixture.cs index 0be41209..7d9f4136 100644 --- a/source/Halibut.Tests/UsageFixture.cs +++ b/source/Halibut.Tests/UsageFixture.cs @@ -18,6 +18,7 @@ namespace Halibut.Tests public class UsageFixture : BaseTest { [Test] + [RetryOnTransportTimeout] [LatestAndPreviousClientAndServiceVersionsTestCases()] public async Task OctopusCanSendMessagesToTentacle_WithEchoService(ClientAndServiceTestCase clientAndServiceTestCase) { @@ -36,6 +37,7 @@ public async Task OctopusCanSendMessagesToTentacle_WithEchoService(ClientAndServ } [Test] + [RetryOnTransportTimeout] [LatestAndPreviousClientAndServiceVersionsTestCases(testNetworkConditions: false)] public async Task LargeMessages(ClientAndServiceTestCase clientAndServiceTestCase) { @@ -58,6 +60,7 @@ public async Task LargeMessages(ClientAndServiceTestCase clientAndServiceTestCas } [Test] + [RetryOnTransportTimeout] [LatestAndPreviousClientAndServiceVersionsTestCases()] public async Task OctopusCanSendMessagesToTentacle_WithSupportedServices(ClientAndServiceTestCase clientAndServiceTestCase) { @@ -77,6 +80,7 @@ public async Task OctopusCanSendMessagesToTentacle_WithSupportedServices(ClientA } [Test] + [RetryOnTransportTimeout] [LatestAndPreviousClientAndServiceVersionsTestCases()] public async Task StreamsCanBeSent(ClientAndServiceTestCase clientAndServiceTestCase) { diff --git a/source/Halibut.Tests/Util/TransportTimeoutClassifierFixture.cs b/source/Halibut.Tests/Util/TransportTimeoutClassifierFixture.cs new file mode 100644 index 00000000..ffbb4aef --- /dev/null +++ b/source/Halibut.Tests/Util/TransportTimeoutClassifierFixture.cs @@ -0,0 +1,74 @@ +using System; +using System.IO; +using System.Net.Sockets; +using FluentAssertions; +using Halibut.Tests.Support; +using Halibut.Transport.Protocol; +using NUnit.Framework; + +namespace Halibut.Tests.Util +{ + public class TransportTimeoutClassifierFixture + { + [Test] + public void SocketTimeoutWrappedInIOExceptionAndHalibutClientException_IsATransportTimeout() + { + var exception = new HalibutClientException("An error occurred when sending a request", + new IOException("Unable to read data from the transport connection", + new SocketException((int)SocketError.TimedOut))); + + TransportTimeoutClassifier.IsTransportTimeout(exception).Should().BeTrue(); + } + + [Test] + public void Net48TimeoutMessageWithoutInnerException_IsATransportTimeout() + { + var exception = new HalibutClientException("Unable to read data from the transport connection: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond."); + + TransportTimeoutClassifier.IsTransportTimeout(exception).Should().BeTrue(); + } + + [Test] + public void PollingRequestNotCollectedInTime_IsATransportTimeout() + { + var exception = new HalibutClientException("A request was sent to a polling endpoint, but the polling endpoint did not collect the request within the allowed time (00:01:06), so the request timed out."); + + TransportTimeoutClassifier.IsTransportTimeout(exception).Should().BeTrue(); + } + + [Test] + public void TimeoutInsideAggregateException_IsATransportTimeout() + { + var exception = new AggregateException(new InvalidOperationException("other"), new SocketException((int)SocketError.TimedOut)); + + TransportTimeoutClassifier.IsTransportTimeout(exception).Should().BeTrue(); + } + + [Test] + public void ConnectionRefused_IsNotATransportTimeout() + { + var exception = new HalibutClientException("An error occurred when sending a request", + new SocketException((int)SocketError.ConnectionRefused)); + + TransportTimeoutClassifier.IsTransportTimeout(exception).Should().BeFalse(); + } + + [Test] + public void ProtocolError_IsNotATransportTimeout() + { + TransportTimeoutClassifier.IsTransportTimeout(new ProtocolException("Expected PROCEED, got something else")).Should().BeFalse(); + } + + [Test] + public void AssertionFailure_IsNotATransportTimeout() + { + TransportTimeoutClassifier.IsTransportTimeout(new AssertionException("Expected 1 but was 2")).Should().BeFalse(); + } + + [Test] + public void Null_IsNotATransportTimeout() + { + TransportTimeoutClassifier.IsTransportTimeout(null).Should().BeFalse(); + } + } +}