Timestamp compat binary output when it is written

source/Halibut.TestUtils.CompatBinary.Base/LogUtils/CompatBinaryLogLine.cs

@@ -0,0 +1,39 @@
+using System;
+using System.Globalization;
+
+namespace Halibut.TestUtils.SampleProgram.Base.LogUtils
+{
+    /// <summary>
+    /// The compat binaries prefix each stdout line with the time it was written, e.g.
+    /// <c>[compat 12:28:14.740Z] Listening on port: 53024</c>.
+    ///
+    /// 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: ".
+    /// </summary>
+    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;
+        }
+
+        /// <summary>
+        /// Returns the line without its timestamp prefix. Lines without a prefix are returned unchanged.
+        /// </summary>
+        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);
+        }
+    }
+}

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

source/Halibut.TestUtils.CompatBinary.Base/LogUtils/NonBlockingLineWriter.cs

@@ -24,13 +24,22 @@ public class NonBlockingLineWriter : IDisposable
         readonly TextWriter target;
         readonly BlockingCollection<string> lines;
         readonly Thread writerThread;
+        readonly Func<DateTime>? utcNow;
         long droppedLines;
         long pendingLines;
 
-        public NonBlockingLineWriter(TextWriter target, int capacity = DefaultCapacity, string threadName = nameof(NonBlockingLineWriter))
+        /// <param name="target">Where lines are written.</param>
+        /// <param name="capacity">How many lines can be queued before new lines are dropped.</param>
+        /// <param name="threadName">The name of the background writer thread.</param>
+        /// <param name="utcNow">
+        /// If set, each line is prefixed with this clock's time when <see cref="WriteLine"/> is called
+        /// (see <see cref="CompatBinaryLogLine"/>), so readers can tell when a line was written rather than read.
+        /// </param>
+        public NonBlockingLineWriter(TextWriter target, int capacity = DefaultCapacity, string threadName = nameof(NonBlockingLineWriter), Func<DateTime>? 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<string>(new ConcurrentQueue<string>(), 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();

source/Halibut.Tests/Halibut.Tests.csproj

@@ -20,6 +20,8 @@
   <ItemGroup>
     <!-- Linked so the compat binary console writer can be unit tested without referencing a compat binary (which pulls in an old Halibut). -->
     <Compile Include="..\Halibut.TestUtils.CompatBinary.Base\LogUtils\NonBlockingLineWriter.cs" Link="Support\BackwardsCompatibility\NonBlockingLineWriter.cs" />
+    <!-- Linked so the test harness strips the compat binary's timestamp prefix in exactly the way the compat binary writes it. -->
+    <Compile Include="..\Halibut.TestUtils.CompatBinary.Base\LogUtils\CompatBinaryLogLine.cs" Link="Support\BackwardsCompatibility\CompatBinaryLogLine.cs" />
   </ItemGroup>
   <ItemGroup>
     <None Update="Certificates/WrongCert.pfx;Certificates\Octopus.pfx;Certificates\Ssl.pfx;Certificates\TentacleListening.pfx;Certificates\TentaclePolling.pfx;appsettings.json">

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

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

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