From 8fa56af97ba95785e993eca64939e025c0df6ebb Mon Sep 17 00:00:00 2001 From: Tod Thomson Date: Tue, 3 Nov 2026 17:58:04 +1000 Subject: [PATCH] Retry net48 UsageFixture tests on transport read timeouts Adds a RetryOnTransportTimeout test attribute. It retries a test only when the test fails with a transport read timeout (socket TimedOut, or a polling request not collected in time); every other failure fails immediately. Retries apply on .NET Framework only by default. Each retry is reported in the test output and, under TeamCity, as a warning plus the 'halibut-transport-timeout-retry' build tag, so the cause stays visible. A retried test keeps its earlier attempt's trace log and is allowed to replace its trace logger. The attribute is applied to the UsageFixture tests whose net48 timeouts have been blocking the nightly Full Chain (LEV-2173, LEV-2244, LEV-2245, LEV-2246). Tests cover the classifier and the retry behaviour. Refs LEV-2253 Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_012CQ12HPMmHGEcvKjdG43mj --- source/Halibut.Tests/BaseTest.cs | 5 +- .../Support/SerilogLoggerBuilder.cs | 5 +- .../RetryOnTransportTimeoutAttribute.cs | 144 ++++++++++++++++++ ...RetryOnTransportTimeoutAttributeFixture.cs | 43 ++++++ .../Support/TransportTimeoutClassifier.cs | 68 +++++++++ source/Halibut.Tests/TraceLogFileLogger.cs | 5 +- source/Halibut.Tests/UsageFixture.cs | 4 + .../Util/TransportTimeoutClassifierFixture.cs | 74 +++++++++ 8 files changed, 343 insertions(+), 5 deletions(-) create mode 100644 source/Halibut.Tests/Support/TestAttributes/RetryOnTransportTimeoutAttribute.cs create mode 100644 source/Halibut.Tests/Support/TestAttributes/RetryOnTransportTimeoutAttributeFixture.cs create mode 100644 source/Halibut.Tests/Support/TransportTimeoutClassifier.cs create mode 100644 source/Halibut.Tests/Util/TransportTimeoutClassifierFixture.cs diff --git a/source/Halibut.Tests/BaseTest.cs b/source/Halibut.Tests/BaseTest.cs index 1ae8d199d..05685301f 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 14220c475..9312ae810 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 000000000..4b36ba4b3 --- /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 000000000..b3df713b1 --- /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 000000000..f59a41484 --- /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 e34b83cfb..8a0dcf82f 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 0be41209d..7d9f4136b 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 000000000..ffbb4aef8 --- /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(); + } + } +}