From be32ba9fefd2ec53d2d414e638d2f5173facc39f Mon Sep 17 00:00:00 2001 From: Claude Date: Tue, 3 Nov 2026 08:13:45 +0000 Subject: [PATCH 1/2] Timestamp compat binary output when it is written The test process timestamps compat binary lines when it reads them, so trace logs can't tell 'the compat binary stopped writing' apart from 'the test process stopped reading' (LEV-2253). NonBlockingConsole now prefixes each line with the UTC time it was written, e.g. '[compat 12:28:14.740Z] ...'. CompatBinaryLogLine owns the format and is linked into Halibut.Tests, where the binary runners strip the prefix before parsing startup lines. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_012CQ12H5eAC2buLoec1L71V --- .../LogUtils/CompatBinaryLogLine.cs | 39 +++++++++++++++++++ .../LogUtils/NonBlockingConsole.cs | 2 +- .../LogUtils/NonBlockingLineWriter.cs | 17 ++++++-- source/Halibut.Tests/Halibut.Tests.csproj | 2 + .../HalibutTestBinaryRunner.cs | 10 +++-- .../ProxyHalibutTestBinaryRunner.cs | 14 ++++--- 6 files changed, 72 insertions(+), 12 deletions(-) create mode 100644 source/Halibut.TestUtils.CompatBinary.Base/LogUtils/CompatBinaryLogLine.cs diff --git a/source/Halibut.TestUtils.CompatBinary.Base/LogUtils/CompatBinaryLogLine.cs b/source/Halibut.TestUtils.CompatBinary.Base/LogUtils/CompatBinaryLogLine.cs new file mode 100644 index 00000000..439b166d --- /dev/null +++ b/source/Halibut.TestUtils.CompatBinary.Base/LogUtils/CompatBinaryLogLine.cs @@ -0,0 +1,39 @@ +using System; +using System.Globalization; + +namespace Halibut.TestUtils.SampleProgram.Base.LogUtils +{ + /// + /// The compat binaries prefix each stdout line with the time it was written, e.g. + /// [compat 12:28:14.740Z] Listening on port: 53024. + /// + /// The test process timestamps lines when it reads them, so without this a trace log cannot tell + /// "the compat binary stopped writing" apart from "the test process stopped reading" (see LEV-2253). + /// + /// This file is linked into Halibut.Tests, so the test harness can strip the prefix before parsing + /// lines such as "Listening on port: ". + /// + public static class CompatBinaryLogLine + { + const string Prefix = "[compat "; + const string Terminator = "Z] "; + + public static string WithTimestamp(DateTime utcNow, string line) + { + return Prefix + utcNow.ToString("HH:mm:ss.fff", CultureInfo.InvariantCulture) + Terminator + line; + } + + /// + /// Returns the line without its timestamp prefix. Lines without a prefix are returned unchanged. + /// + public static string WithoutTimestamp(string line) + { + if (!line.StartsWith(Prefix, StringComparison.Ordinal)) return line; + + var terminatorIndex = line.IndexOf(Terminator, Prefix.Length, StringComparison.Ordinal); + if (terminatorIndex < 0) return line; + + return line.Substring(terminatorIndex + Terminator.Length); + } + } +} diff --git a/source/Halibut.TestUtils.CompatBinary.Base/LogUtils/NonBlockingConsole.cs b/source/Halibut.TestUtils.CompatBinary.Base/LogUtils/NonBlockingConsole.cs index 5eab161e..b322eb86 100644 --- a/source/Halibut.TestUtils.CompatBinary.Base/LogUtils/NonBlockingConsole.cs +++ b/source/Halibut.TestUtils.CompatBinary.Base/LogUtils/NonBlockingConsole.cs @@ -11,7 +11,7 @@ public static class NonBlockingConsole { static readonly TimeSpan DefaultFlushTimeout = TimeSpan.FromSeconds(10); - static readonly NonBlockingLineWriter Writer = new(Console.Out, threadName: "CompatBinaryConsoleWriter"); + static readonly NonBlockingLineWriter Writer = new(Console.Out, threadName: "CompatBinaryConsoleWriter", utcNow: () => DateTime.UtcNow); public static void WriteLine(string line) => Writer.WriteLine(line); diff --git a/source/Halibut.TestUtils.CompatBinary.Base/LogUtils/NonBlockingLineWriter.cs b/source/Halibut.TestUtils.CompatBinary.Base/LogUtils/NonBlockingLineWriter.cs index 2041b252..085ccee1 100644 --- a/source/Halibut.TestUtils.CompatBinary.Base/LogUtils/NonBlockingLineWriter.cs +++ b/source/Halibut.TestUtils.CompatBinary.Base/LogUtils/NonBlockingLineWriter.cs @@ -24,13 +24,22 @@ public class NonBlockingLineWriter : IDisposable readonly TextWriter target; readonly BlockingCollection lines; readonly Thread writerThread; + readonly Func? utcNow; long droppedLines; long pendingLines; - public NonBlockingLineWriter(TextWriter target, int capacity = DefaultCapacity, string threadName = nameof(NonBlockingLineWriter)) + /// Where lines are written. + /// How many lines can be queued before new lines are dropped. + /// The name of the background writer thread. + /// + /// If set, each line is prefixed with this clock's time when is called + /// (see ), so readers can tell when a line was written rather than read. + /// + public NonBlockingLineWriter(TextWriter target, int capacity = DefaultCapacity, string threadName = nameof(NonBlockingLineWriter), Func? utcNow = null) { if (capacity <= 0) throw new ArgumentOutOfRangeException(nameof(capacity), capacity, "Capacity must be greater than zero."); + this.utcNow = utcNow; this.target = target ?? throw new ArgumentNullException(nameof(target)); lines = new BlockingCollection(new ConcurrentQueue(), capacity); writerThread = new Thread(WriteLoop) @@ -57,7 +66,7 @@ public void WriteLine(string line) bool added; try { - added = lines.TryAdd(line); + added = lines.TryAdd(Timestamped(line)); } catch (InvalidOperationException) { @@ -113,7 +122,7 @@ void WriteLoop() var dropped = Interlocked.Exchange(ref droppedLines, 0); if (dropped > 0) { - target.WriteLine($"[{nameof(NonBlockingLineWriter)}] {dropped} log line(s) were dropped because the output was not being read."); + target.WriteLine(Timestamped($"[{nameof(NonBlockingLineWriter)}] {dropped} log line(s) were dropped because the output was not being read.")); } target.WriteLine(line); @@ -131,6 +140,8 @@ void WriteLoop() } } + string Timestamped(string line) => utcNow is null ? line : CompatBinaryLogLine.WithTimestamp(utcNow(), line); + public void Dispose() { lines.CompleteAdding(); diff --git a/source/Halibut.Tests/Halibut.Tests.csproj b/source/Halibut.Tests/Halibut.Tests.csproj index e59695d8..53d5d6b8 100644 --- a/source/Halibut.Tests/Halibut.Tests.csproj +++ b/source/Halibut.Tests/Halibut.Tests.csproj @@ -20,6 +20,8 @@ + + diff --git a/source/Halibut.Tests/Support/BackwardsCompatibility/HalibutTestBinaryRunner.cs b/source/Halibut.Tests/Support/BackwardsCompatibility/HalibutTestBinaryRunner.cs index 35cdaa45..1da8f1e8 100644 --- a/source/Halibut.Tests/Support/BackwardsCompatibility/HalibutTestBinaryRunner.cs +++ b/source/Halibut.Tests/Support/BackwardsCompatibility/HalibutTestBinaryRunner.cs @@ -6,6 +6,7 @@ using CliWrap; using Halibut.Logging; using Halibut.Tests.Support.ExtensionMethods; +using Halibut.TestUtils.SampleProgram.Base.LogUtils; using Nito.AsyncEx; using NUnit.Framework; using Serilog; @@ -153,12 +154,15 @@ async Task ProcessLogs(string s, CancellationToken ct) { await Task.CompletedTask; logger.Information(s); - if (s.StartsWith("Listening on port: ")) + + // Log the line with the compat binary's own timestamp, but parse it without. + var line = CompatBinaryLogLine.WithoutTimestamp(s); + if (line.StartsWith("Listening on port: ")) { - serviceListenPort = int.Parse(Regex.Match(s, @"\d+").Value); + serviceListenPort = int.Parse(Regex.Match(line, @"\d+").Value); } - if (s.Contains("RunningAndReady")) hasTentacleStarted.Set(); + if (line.Contains("RunningAndReady")) hasTentacleStarted.Set(); } await Cli.Wrap(new HalibutTestBinaryPath().BinPath(version!)) diff --git a/source/Halibut.Tests/Support/BackwardsCompatibility/ProxyHalibutTestBinaryRunner.cs b/source/Halibut.Tests/Support/BackwardsCompatibility/ProxyHalibutTestBinaryRunner.cs index 0fd3a98a..4f35bee6 100644 --- a/source/Halibut.Tests/Support/BackwardsCompatibility/ProxyHalibutTestBinaryRunner.cs +++ b/source/Halibut.Tests/Support/BackwardsCompatibility/ProxyHalibutTestBinaryRunner.cs @@ -6,6 +6,7 @@ using System.Threading.Tasks; using CliWrap; using Halibut.Logging; +using Halibut.TestUtils.SampleProgram.Base.LogUtils; using Nito.AsyncEx; using Serilog; @@ -131,18 +132,21 @@ async Task ProcessLogs(string s, CancellationToken ct) { await Task.CompletedTask; logger.Information(s); - if (s.StartsWith("Listening on port: ")) + + // Log the line with the compat binary's own timestamp, but parse it without. + var line = CompatBinaryLogLine.WithoutTimestamp(s); + if (line.StartsWith("Listening on port: ")) { - serviceListenPort = int.Parse(Regex.Match(s, @"\d+").Value); + serviceListenPort = int.Parse(Regex.Match(line, @"\d+").Value); logger.Information("External halibut binary listening port is: " + serviceListenPort); } - if (s.StartsWith("Polling listener is listening on port: ")) + if (line.StartsWith("Polling listener is listening on port: ")) { - proxyClientListenPort = int.Parse(Regex.Match(s, @"\d+").Value); + proxyClientListenPort = int.Parse(Regex.Match(line, @"\d+").Value); } - if (s.Contains("RunningAndReady")) hasTentacleStarted.Set(); + if (line.Contains("RunningAndReady")) hasTentacleStarted.Set(); } }, runningTentacleCancellationTokenSource.Token); From 95b7a2a1772895906f6cbc5c4f07e6df2dab151d Mon Sep 17 00:00:00 2001 From: Claude Date: Tue, 3 Nov 2026 08:14:13 +0000 Subject: [PATCH 2/2] Add tests for compat binary log timestamps Covers the timestamp prefix format, stripping it (and leaving unprefixed lines alone), and that NonBlockingLineWriter stamps lines when WriteLine is called rather than when they reach the target. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_012CQ12H5eAC2buLoec1L71V --- .../CompatBinaryLogLineFixture.cs | 68 +++++++++++++++++++ 1 file changed, 68 insertions(+) create mode 100644 source/Halibut.Tests/Support/BackwardsCompatibility/CompatBinaryLogLineFixture.cs diff --git a/source/Halibut.Tests/Support/BackwardsCompatibility/CompatBinaryLogLineFixture.cs b/source/Halibut.Tests/Support/BackwardsCompatibility/CompatBinaryLogLineFixture.cs new file mode 100644 index 00000000..a37462f3 --- /dev/null +++ b/source/Halibut.Tests/Support/BackwardsCompatibility/CompatBinaryLogLineFixture.cs @@ -0,0 +1,68 @@ +using System; +using System.IO; +using System.Threading.Tasks; +using FluentAssertions; +using Halibut.TestUtils.SampleProgram.Base.LogUtils; +using NUnit.Framework; + +namespace Halibut.Tests.Support.BackwardsCompatibility +{ + public class CompatBinaryLogLineFixture : BaseTest + { + static readonly DateTime WrittenAt = new(2026, 11, 1, 12, 28, 14, 740, DateTimeKind.Utc); + + [Test] + public void WithTimestamp_PrefixesTheTimeTheLineWasWritten() + { + CompatBinaryLogLine.WithTimestamp(WrittenAt, "Listening on port: 53024") + .Should().Be("[compat 12:28:14.740Z] Listening on port: 53024"); + } + + [TestCase("Listening on port: 53024")] + [TestCase("RunningAndReady")] + [TestCase("Polling listener is listening on port: 53127")] + [TestCase("[compat ] not a timestamp")] + [TestCase("")] + public void WithoutTimestamp_RoundTrips(string line) + { + CompatBinaryLogLine.WithoutTimestamp(CompatBinaryLogLine.WithTimestamp(WrittenAt, line)) + .Should().Be(line); + } + + [TestCase("Listening on port: 53024")] + [TestCase("Compat binary is still running")] + [TestCase("[compat without a terminator")] + public void WithoutTimestamp_LeavesLinesWithoutAPrefixUnchanged(string line) + { + CompatBinaryLogLine.WithoutTimestamp(line).Should().Be(line); + } + + [Test] + public async Task NonBlockingLineWriter_TimestampsLinesWhenTheyAreWritten_NotWhenTheyReachTheTarget() + { + var now = WrittenAt; + var target = new StringWriter(); + using var writer = new NonBlockingLineWriter(target, utcNow: () => now); + + writer.WriteLine("first"); + now = now.AddSeconds(1); + writer.WriteLine("second"); + (await writer.FlushAsync(TimeSpan.FromSeconds(10))).Should().BeTrue(); + + target.ToString().Split(new[] { Environment.NewLine }, StringSplitOptions.RemoveEmptyEntries) + .Should().Equal("[compat 12:28:14.740Z] first", "[compat 12:28:15.740Z] second"); + } + + [Test] + public async Task NonBlockingLineWriter_DoesNotTimestampLinesWithoutAClock() + { + var target = new StringWriter(); + using var writer = new NonBlockingLineWriter(target); + + writer.WriteLine("plain"); + (await writer.FlushAsync(TimeSpan.FromSeconds(10))).Should().BeTrue(); + + target.ToString().Trim().Should().Be("plain"); + } + } +}