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/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"); + } + } +} 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);