From 0e2c8203a9030538b48cd7796a35d3c5dc4a9ba5 Mon Sep 17 00:00:00 2001 From: Luke Butters Date: Thu, 12 Nov 2026 13:05:20 +1100 Subject: [PATCH 1/2] Repro: stall compat binary stdout to reproduce net48 transport timeouts Set HALIBUT_REPRO_STALL_COMPAT_STDOUT=1 to stop reading the compat binary's stdout after RunningAndReady. Without the NonBlockingConsoleWriter fix the vService:5.0.236 cases of CompatStdoutStallReproFixture fail with read timeouts / 'polling endpoint did not collect the request'. Set HALIBUT_REPRO_COMPAT_TRACE_DIR to trace console writes inside the compat binary. --- .../BackwardsCompatProgramBase.cs | 1 + .../LogUtils/NonBlockingConsoleWriter.cs | 86 +++++++++++++++++++ .../CompatStdoutStallReproFixture.cs | 32 +++++++ .../HalibutTestBinaryRunner.cs | 10 ++- 4 files changed, 128 insertions(+), 1 deletion(-) create mode 100644 source/Halibut.TestUtils.CompatBinary.Base/LogUtils/NonBlockingConsoleWriter.cs create mode 100644 source/Halibut.Tests/CompatStdoutStallReproFixture.cs diff --git a/source/Halibut.TestUtils.CompatBinary.Base/BackwardsCompatProgramBase.cs b/source/Halibut.TestUtils.CompatBinary.Base/BackwardsCompatProgramBase.cs index 80b624fee..7fbc2a5e3 100644 --- a/source/Halibut.TestUtils.CompatBinary.Base/BackwardsCompatProgramBase.cs +++ b/source/Halibut.TestUtils.CompatBinary.Base/BackwardsCompatProgramBase.cs @@ -10,6 +10,7 @@ public class BackwardsCompatProgramBase { public static async Task Main() { + NonBlockingConsoleWriter.Install(); using var cancellationTokenSource = new CancellationTokenSource(SettingsHelper.GetTestTimeout()); using var registration = cancellationTokenSource.Token.Register(() => { diff --git a/source/Halibut.TestUtils.CompatBinary.Base/LogUtils/NonBlockingConsoleWriter.cs b/source/Halibut.TestUtils.CompatBinary.Base/LogUtils/NonBlockingConsoleWriter.cs new file mode 100644 index 000000000..163a58f32 --- /dev/null +++ b/source/Halibut.TestUtils.CompatBinary.Base/LogUtils/NonBlockingConsoleWriter.cs @@ -0,0 +1,86 @@ +using System; +using System.Collections.Concurrent; +using System.IO; +using System.Runtime.InteropServices; +using Microsoft.Win32.SafeHandles; +using System.Text; +using System.Threading; + +namespace Halibut.TestUtils.SampleProgram.Base.LogUtils +{ + /// + /// The test reads our stdout through a pipe. If it stops reading, a blocking Console.Write + /// freezes Halibut mid-exchange, so writes are queued and dropped when the queue is full. + /// + public class NonBlockingConsoleWriter : TextWriter + { + const int MaxQueuedWrites = 10_000; + + readonly TextWriter destination; + readonly BlockingCollection queue = new(MaxQueuedWrites); + long droppedWrites; + + NonBlockingConsoleWriter(Stream destination) + { + this.destination = new StreamWriter(destination, new UTF8Encoding(false)) { AutoFlush = false }; + new Thread(Drain) { IsBackground = true, Name = "NonBlockingConsoleWriter" }.Start(); + } + + public static void Install() + { + Console.SetOut(new NonBlockingConsoleWriter(OpenStandardStream(1, Console.OpenStandardOutput))); + Console.SetError(new NonBlockingConsoleWriter(OpenStandardStream(2, Console.OpenStandardError))); + Trace("installed " + Console.Out.GetType().FullName); + } + + // On Unix the console stream locks Console.Out while writing, so a stalled pipe would + // still block every Console.WriteLine. Write to the raw file descriptor instead. + static Stream OpenStandardStream(int fileDescriptor, Func openConsoleStream) + { + if (RuntimeInformation.IsOSPlatform(OSPlatform.Windows)) return openConsoleStream(); + return new FileStream(new SafeFileHandle((IntPtr)fileDescriptor, ownsHandle: false), FileAccess.Write, 1); + } + + public override Encoding Encoding => destination.Encoding; + + public override void Write(char value) => Enqueue(value.ToString()); + + public override void Write(string? value) + { + if (value is not null) Enqueue(value); + } + + public override void WriteLine(string? value) => Enqueue(value + new string(CoreNewLine)); + + static readonly string? TraceFile = Environment.GetEnvironmentVariable("HALIBUT_REPRO_COMPAT_TRACE_DIR") is { } dir + ? Path.Combine(dir, $"compat-trace-{System.Diagnostics.Process.GetCurrentProcess().Id}.txt") + : null; + static readonly object TraceLock = new(); + + static void Trace(string what) + { + if (TraceFile is null) return; + lock (TraceLock) File.AppendAllText(TraceFile, $"{DateTime.Now:HH:mm:ss.fff} t{Thread.CurrentThread.ManagedThreadId} {what}\n"); + } + + void Enqueue(string value) + { + Trace("enqueue-start " + value.Substring(0, Math.Min(60, value.Length)).Replace("\n", " ")); + if (!queue.TryAdd(value)) Interlocked.Increment(ref droppedWrites); + Trace("enqueue-done"); + } + + void Drain() + { + foreach (var value in queue.GetConsumingEnumerable()) + { + var dropped = Interlocked.Exchange(ref droppedWrites, 0); + if (dropped > 0) destination.WriteLine($"[NonBlockingConsoleWriter dropped {dropped} writes]"); + + Trace("drain-write-start"); + destination.Write(value); + if (queue.Count == 0) destination.Flush(); + } + } + } +} diff --git a/source/Halibut.Tests/CompatStdoutStallReproFixture.cs b/source/Halibut.Tests/CompatStdoutStallReproFixture.cs new file mode 100644 index 000000000..701dde6b5 --- /dev/null +++ b/source/Halibut.Tests/CompatStdoutStallReproFixture.cs @@ -0,0 +1,32 @@ +using System; +using System.Threading.Tasks; +using FluentAssertions; +using Halibut.Tests.Support; +using Halibut.Tests.Support.TestAttributes; +using Halibut.Tests.Support.TestCases; +using Halibut.Tests.TestServices.Async; +using Halibut.TestUtils.Contracts; +using NUnit.Framework; + +namespace Halibut.Tests +{ + public class CompatStdoutStallReproFixture : BaseTest + { + [Test] + [LatestAndPreviousClientAndServiceVersionsTestCases(testNetworkConditions: false)] + public async Task EchoUntilCompatStdoutFills(ClientAndServiceTestCase clientAndServiceTestCase) + { + await using var clientAndService = await clientAndServiceTestCase.CreateTestCaseBuilder() + .WithStandardServices() + .Build(CancellationToken); + + var echo = clientAndService.CreateAsyncClient(); + var payload = new string('x', 1024); + for (var i = 0; i < 2000; i++) + { + Logger.Information("REPRO: echo {I}", i); + (await echo.SayHelloAsync($"{i} {payload}")).Should().Be($"{i} {payload}..."); + } + } + } +} diff --git a/source/Halibut.Tests/Support/BackwardsCompatibility/HalibutTestBinaryRunner.cs b/source/Halibut.Tests/Support/BackwardsCompatibility/HalibutTestBinaryRunner.cs index 35cdaa459..cc0013d1f 100644 --- a/source/Halibut.Tests/Support/BackwardsCompatibility/HalibutTestBinaryRunner.cs +++ b/source/Halibut.Tests/Support/BackwardsCompatibility/HalibutTestBinaryRunner.cs @@ -158,7 +158,15 @@ async Task ProcessLogs(string s, CancellationToken ct) serviceListenPort = int.Parse(Regex.Match(s, @"\d+").Value); } - if (s.Contains("RunningAndReady")) hasTentacleStarted.Set(); + if (s.Contains("RunningAndReady")) + { + hasTentacleStarted.Set(); + if (Environment.GetEnvironmentVariable("HALIBUT_REPRO_STALL_COMPAT_STDOUT") == "1") + { + logger.Information("REPRO: compat stdout pump stalled; no further compat output will be read"); + await Task.Delay(Timeout.Infinite, ct); + } + } } await Cli.Wrap(new HalibutTestBinaryPath().BinPath(version!)) From dbb131ed91935eb69b08b09aa503b78dd644cc08 Mon Sep 17 00:00:00 2001 From: Luke Butters Date: Thu, 12 Nov 2026 13:06:17 +1100 Subject: [PATCH 2/2] Make compat binary console output non-blocking The test harness reads the compat binary's stdout through a pipe. If that reader stalls, Console.WriteLine in the compat binary blocks and freezes Halibut mid-exchange, surfacing as transport read timeouts in net48 tests. Queue console writes on a background thread and drop them when the queue is full so logging can never block the protocol. --- .../LogUtils/NonBlockingConsoleWriter.cs | 15 --------- .../CompatStdoutStallReproFixture.cs | 32 ------------------- .../HalibutTestBinaryRunner.cs | 10 +----- 3 files changed, 1 insertion(+), 56 deletions(-) delete mode 100644 source/Halibut.Tests/CompatStdoutStallReproFixture.cs diff --git a/source/Halibut.TestUtils.CompatBinary.Base/LogUtils/NonBlockingConsoleWriter.cs b/source/Halibut.TestUtils.CompatBinary.Base/LogUtils/NonBlockingConsoleWriter.cs index 163a58f32..1e25bc98c 100644 --- a/source/Halibut.TestUtils.CompatBinary.Base/LogUtils/NonBlockingConsoleWriter.cs +++ b/source/Halibut.TestUtils.CompatBinary.Base/LogUtils/NonBlockingConsoleWriter.cs @@ -30,7 +30,6 @@ public static void Install() { Console.SetOut(new NonBlockingConsoleWriter(OpenStandardStream(1, Console.OpenStandardOutput))); Console.SetError(new NonBlockingConsoleWriter(OpenStandardStream(2, Console.OpenStandardError))); - Trace("installed " + Console.Out.GetType().FullName); } // On Unix the console stream locks Console.Out while writing, so a stalled pipe would @@ -52,22 +51,9 @@ public override void Write(string? value) public override void WriteLine(string? value) => Enqueue(value + new string(CoreNewLine)); - static readonly string? TraceFile = Environment.GetEnvironmentVariable("HALIBUT_REPRO_COMPAT_TRACE_DIR") is { } dir - ? Path.Combine(dir, $"compat-trace-{System.Diagnostics.Process.GetCurrentProcess().Id}.txt") - : null; - static readonly object TraceLock = new(); - - static void Trace(string what) - { - if (TraceFile is null) return; - lock (TraceLock) File.AppendAllText(TraceFile, $"{DateTime.Now:HH:mm:ss.fff} t{Thread.CurrentThread.ManagedThreadId} {what}\n"); - } - void Enqueue(string value) { - Trace("enqueue-start " + value.Substring(0, Math.Min(60, value.Length)).Replace("\n", " ")); if (!queue.TryAdd(value)) Interlocked.Increment(ref droppedWrites); - Trace("enqueue-done"); } void Drain() @@ -77,7 +63,6 @@ void Drain() var dropped = Interlocked.Exchange(ref droppedWrites, 0); if (dropped > 0) destination.WriteLine($"[NonBlockingConsoleWriter dropped {dropped} writes]"); - Trace("drain-write-start"); destination.Write(value); if (queue.Count == 0) destination.Flush(); } diff --git a/source/Halibut.Tests/CompatStdoutStallReproFixture.cs b/source/Halibut.Tests/CompatStdoutStallReproFixture.cs deleted file mode 100644 index 701dde6b5..000000000 --- a/source/Halibut.Tests/CompatStdoutStallReproFixture.cs +++ /dev/null @@ -1,32 +0,0 @@ -using System; -using System.Threading.Tasks; -using FluentAssertions; -using Halibut.Tests.Support; -using Halibut.Tests.Support.TestAttributes; -using Halibut.Tests.Support.TestCases; -using Halibut.Tests.TestServices.Async; -using Halibut.TestUtils.Contracts; -using NUnit.Framework; - -namespace Halibut.Tests -{ - public class CompatStdoutStallReproFixture : BaseTest - { - [Test] - [LatestAndPreviousClientAndServiceVersionsTestCases(testNetworkConditions: false)] - public async Task EchoUntilCompatStdoutFills(ClientAndServiceTestCase clientAndServiceTestCase) - { - await using var clientAndService = await clientAndServiceTestCase.CreateTestCaseBuilder() - .WithStandardServices() - .Build(CancellationToken); - - var echo = clientAndService.CreateAsyncClient(); - var payload = new string('x', 1024); - for (var i = 0; i < 2000; i++) - { - Logger.Information("REPRO: echo {I}", i); - (await echo.SayHelloAsync($"{i} {payload}")).Should().Be($"{i} {payload}..."); - } - } - } -} diff --git a/source/Halibut.Tests/Support/BackwardsCompatibility/HalibutTestBinaryRunner.cs b/source/Halibut.Tests/Support/BackwardsCompatibility/HalibutTestBinaryRunner.cs index cc0013d1f..35cdaa459 100644 --- a/source/Halibut.Tests/Support/BackwardsCompatibility/HalibutTestBinaryRunner.cs +++ b/source/Halibut.Tests/Support/BackwardsCompatibility/HalibutTestBinaryRunner.cs @@ -158,15 +158,7 @@ async Task ProcessLogs(string s, CancellationToken ct) serviceListenPort = int.Parse(Regex.Match(s, @"\d+").Value); } - if (s.Contains("RunningAndReady")) - { - hasTentacleStarted.Set(); - if (Environment.GetEnvironmentVariable("HALIBUT_REPRO_STALL_COMPAT_STDOUT") == "1") - { - logger.Information("REPRO: compat stdout pump stalled; no further compat output will be read"); - await Task.Delay(Timeout.Infinite, ct); - } - } + if (s.Contains("RunningAndReady")) hasTentacleStarted.Set(); } await Cli.Wrap(new HalibutTestBinaryPath().BinPath(version!))