Retry net48 UsageFixture tests on transport read timeouts

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;
         }

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;

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
+{
+    /// <summary>
+    /// Retries a test only when it fails with a transport read timeout (see <see cref="TransportTimeoutClassifier"/>).
+    /// 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.
+    /// </summary>
+    [AttributeUsage(AttributeTargets.Method, AllowMultiple = false, Inherited = false)]
+    public class RetryOnTransportTimeoutAttribute : NUnitAttribute, IRepeatTest, IWrapTestMethod
+    {
+        public const string TeamCityBuildTag = "halibut-transport-timeout-retry";
+
+        static readonly ConditionalWeakTable<Test, ExceptionHolder> LastExceptionByTest = new();
+
+        readonly int tryCount;
+        readonly bool netFrameworkOnly;
+
+        /// <param name="tryCount">Total number of attempts, including the first.</param>
+        /// <param name="netFrameworkOnly">When true, tests run once (no retries) on modern .NET.</param>
+        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("]", "|]");
+        }
+    }
+}

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<string, int> 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);
+        }
+    }
+}

source/Halibut.Tests/Support/TransportTimeoutClassifier.cs

@@ -0,0 +1,68 @@
+using System;
+using System.Collections.Generic;
+using System.Net.Sockets;
+
+namespace Halibut.Tests.Support
+{
+    /// <summary>
+    /// 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 <see cref="Halibut.Diagnostics.ExceptionReturnedByHalibutProxyExtensionMethod.IsNetworkError"/>:
+    /// connection refused, resets, protocol errors, certificate problems and assertion failures are NOT matched.
+    /// </summary>
+    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<Exception> 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;
+            }
+        }
+    }
+}

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)
+        /// <param name="appendToExisting">True when a test is being retried (see RetryOnTransportTimeoutAttribute), so the earlier attempt's log is kept.</param>
+        public TraceLogFileLogger(string testHash, bool appendToExisting = false)
         {
             this.testHash = testHash;
             this.logFilePath = LogFilePath(testHash);
-            File.Delete(logFilePath);
+            if (!appendToExisting) File.Delete(logFilePath);
 
             writeDataToDiskTask = WriteDataToFile();
         }

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)
         {