Skip to content

De-flake Hosting semantic-logging specs: 10 s for the logger, thread-safe test logger - #8624

Merged
Aaronontheweb merged 1 commit into
akkadotnet:devfrom
Aaronontheweb:fix/hosting-semantic-logging-timeout
Sep 24, 2026
Merged

Aaronontheweb merged 1 commit into
akkadotnet:devfrom
Aaronontheweb:fix/hosting-semantic-logging-timeout

Conversation

@Aaronontheweb

Copy link
Copy Markdown
Member

Akka.Hosting.Tests.Logging.SemanticLoggingSpecs.MultipleNamedPropertiesTest ("Should handle multiple named properties in template") failed on a 2-vCPU Windows agent: Assertion did not pass within 3s — Expected _logger.LogEntries not to be empty. It showed up in a duplicate branch build of AOT-stack PR #8603's head. The PR build of the same commit passed the whole Akka.Hosting.Tests suite.

Cause: the logger was late, not lossy

The test output contains the captured line [INFO][05:05:29.121Z] ... Order ORD-001 ..., which made it look as if the entry arrived in time and then vanished. But that timestamp is the event's, taken when the actor called log.Info, not the time the test logger printed it. xUnit's output buffer records no write times.

In the buffer, the line sits right before "Disposing system" at 32.426. So the LoggerFactoryLogger actor, which runs on the default dispatcher, most likely reached the event only as the 3 s assertion ran out. SemanticTestLogger.Log has no path that prints without recording, and the helper re-reads LogEntries on every retry.

Change

  • The fix: both helpers (SemanticLoggingSpecs, WithContextSpecs) now wait 10 s instead of 3 s by default.
  • Diagnostics: SemanticTestLogger prints the wall-clock time it logged the entry, so if this recurs the log will show when the logger actually got to it.
  • Hygiene: LogEntries becomes a ConcurrentQueue<LogEntry>, since it's written on the logger actor's thread and read on the test's. Issue701SemanticLoggingRegressionSpecs and LogStateSnapshotSpecs already do this. ReceivedLogs now uses Interlocked/Volatile. This doesn't fix the flake, but the old List<T> was a real data race.

This covers all 7 tests in SemanticLoggingSpecs and all 4 in WithContextSpecs.

Verification (local)

  • The two spec classes pass 11/11 across 3 runs.

…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.
@Aaronontheweb
Aaronontheweb merged commit 8bc7e44 into akkadotnet:dev Sep 24, 2026
15 checks passed
@Aaronontheweb
Aaronontheweb deleted the fix/hosting-semantic-logging-timeout branch September 24, 2026 12:30
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant