From 89645f8c928269d82072feb58c94e1b3fa97e0f6 Mon Sep 17 00:00:00 2001 From: Aaron Stannard Date: Thu, 24 Sep 2026 05:42:29 +0000 Subject: [PATCH] Hosting SemanticLoggingSpecs/WithContextSpecs: give the logger 10 s, make SemanticTestLogger thread-safe SemanticLoggingSpecs.MultipleNamedPropertiesTest failed on a 2-vCPU Windows agent: its AwaitAssertAsync gave up after 3 s with LogEntries empty. The captured line in the output carries the EVENT's timestamp (29.121), not the time the logger printed it; it sits right before "Disposing system" (32.426), i.e. the LoggerFactoryLogger actor (default dispatcher) most likely reached the event only as the 3 s ran out. Nothing was lost. - Both helpers' default AwaitAssertAsync timeout goes from 3 s to 10 s. - SemanticTestLogger prints the wall-clock time it logged at, so the next failure shows when the logger actually got to the event. - LogEntries becomes a ConcurrentQueue (written on the logger's thread, read on the test's; siblings Issue701SemanticLoggingRegressionSpecs and LogStateSnapshotSpecs already do this) and ReceivedLogs uses Interlocked. --- .../Logging/SemanticLoggingSpecs.cs | 22 ++++++++++++------- .../Logging/WithContextSpecs.cs | 6 +++-- 2 files changed, 18 insertions(+), 10 deletions(-) diff --git a/src/contrib/hosting/Akka.Hosting.Tests/Logging/SemanticLoggingSpecs.cs b/src/contrib/hosting/Akka.Hosting.Tests/Logging/SemanticLoggingSpecs.cs index 23eeffb057a..771297d158a 100644 --- a/src/contrib/hosting/Akka.Hosting.Tests/Logging/SemanticLoggingSpecs.cs +++ b/src/contrib/hosting/Akka.Hosting.Tests/Logging/SemanticLoggingSpecs.cs @@ -1,10 +1,11 @@ -// ----------------------------------------------------------------------- +// ----------------------------------------------------------------------- // // Copyright (C) 2013-2025 .NET Foundation // // ----------------------------------------------------------------------- using System; +using System.Collections.Concurrent; using System.Collections.Generic; using System.Linq; using System.Threading; @@ -241,7 +242,9 @@ private async Task WaitUntilSilent(TimeSpan timeout) private async Task AwaitAssertAsync(Action assertion, TimeSpan? timeout = null, TimeSpan? interval = null) { - var maxWait = timeout ?? TimeSpan.FromSeconds(3); + // The logger actor runs on the default dispatcher; on a starved CI agent it has been seen to reach + // an event ~3 s after it was published, so 3 s left no slack. + var maxWait = timeout ?? TimeSpan.FromSeconds(10); var checkInterval = interval ?? TimeSpan.FromMilliseconds(100); var cts = new CancellationTokenSource(maxWait); @@ -334,8 +337,10 @@ private static object ParseArg(string arg) public class SemanticTestLogger : ILogger { private readonly ITestOutputHelper _helper; - public readonly List LogEntries = new(); - public int ReceivedLogs { get; private set; } + // Written on the logger actor's thread, read on the test's; ConcurrentQueue is safe for both. + public readonly ConcurrentQueue LogEntries = new(); + private int _receivedLogs; + public int ReceivedLogs => Volatile.Read(ref _receivedLogs); public SemanticTestLogger(ITestOutputHelper helper) { @@ -345,15 +350,16 @@ public SemanticTestLogger(ITestOutputHelper helper) public void Clear() { LogEntries.Clear(); - ReceivedLogs = 0; + Interlocked.Exchange(ref _receivedLogs, 0); } public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) { var message = formatter(state, exception); - _helper.WriteLine($"[{logLevel}] {message}"); - ReceivedLogs++; + // the wall-clock print time, not the event's own timestamp: shows when the logger actually got to it + _helper.WriteLine($"{DateTime.UtcNow:HH:mm:ss.fff} [{logLevel}] {message}"); + Interlocked.Increment(ref _receivedLogs); // Capture state as dictionary for semantic logging assertions var stateDict = new Dictionary(); @@ -365,7 +371,7 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, } } - LogEntries.Add(new LogEntry + LogEntries.Enqueue(new LogEntry { LogLevel = logLevel, Message = message, diff --git a/src/contrib/hosting/Akka.Hosting.Tests/Logging/WithContextSpecs.cs b/src/contrib/hosting/Akka.Hosting.Tests/Logging/WithContextSpecs.cs index 1dc3bc7fb78..94847448e74 100644 --- a/src/contrib/hosting/Akka.Hosting.Tests/Logging/WithContextSpecs.cs +++ b/src/contrib/hosting/Akka.Hosting.Tests/Logging/WithContextSpecs.cs @@ -1,4 +1,4 @@ -// ----------------------------------------------------------------------- +// ----------------------------------------------------------------------- // // Copyright (C) 2013-2025 .NET Foundation // @@ -173,7 +173,9 @@ private async Task WaitUntilSilent(TimeSpan timeout) private async Task AwaitAssertAsync(Action assertion, TimeSpan? timeout = null, TimeSpan? interval = null) { - var maxWait = timeout ?? TimeSpan.FromSeconds(3); + // The logger actor runs on the default dispatcher; on a starved CI agent it has been seen to reach + // an event ~3 s after it was published, so 3 s left no slack. + var maxWait = timeout ?? TimeSpan.FromSeconds(10); var checkInterval = interval ?? TimeSpan.FromMilliseconds(100); var cts = new CancellationTokenSource(maxWait);