Skip to content

De-flake LoggerStartupSpec: gate the slow logger instead of racing a fixed delay - #8621

Merged
Aaronontheweb merged 1 commit into
akkadotnet:devfrom
Aaronontheweb:fix/loggerstartupspec-subscribe-race
Sep 24, 2026
Merged

Aaronontheweb merged 1 commit into
akkadotnet:devfrom
Aaronontheweb:fix/loggerstartupspec-subscribe-race

Conversation

@Aaronontheweb

Copy link
Copy Markdown
Member

LoggerStartupSpec.ActorSystem_should_start_with_loggers_timing_out(useAsync: True) failed on a 2-vCPU Windows agent with Timeout 00:00:03 while waiting for a message of type Akka.Event.Debug. It appeared in a build of AOT-stack PR #8608.

Not caused by the AOT stack

The stack changes LoggingBus.StartDefaultLoggers (#8603), so I checked that first:

  • The Settings.cs diff between dev and the stack is empty.
  • A custom logger like SlowLoggerActor falls through to the same Type.GetType call.
  • The Task.WaitAll(logger-startup-timeout) block and the log messages it publishes are byte-identical.

Cause: publish before subscribe

  1. SlowLoggerActor answers InitializeLogger after a fixed 1 s. logger-startup-timeout is 100 ms, so ActorSystem.Create gives up waiting and returns.
  2. LoggingBus later publishes its one-shot Debug, "Logger … SlowLoggerActor … started", once the logger answers.
  3. The test subscribes logProbe to the EventStream only after Create returns.
  4. On the agent, Create stalled about 900 ms. The Debug went out at 53.582 and the subscription happened at about 53.583. The EventStream doesn't replay old messages, so the synchronous ExpectMsg<Debug> spent the whole AwaitAssert budget waiting.

useAsync: False has the same exposure, because akka.logger-async-start isn't read anywhere at runtime.

Change

  • SlowLoggerActor now replies to InitializeLogger when a gate the test controls opens (Release.Task.PipeTo), not after a fixed delay.
  • The gate stays shut for all of Create, so the logger still always misses the 100 ms window. That's the behavior under test.
  • The test opens the gate only after it has subscribed, so the "started" Debug can't be published before anyone is listening. The finally block releases the gate.
  • The two synchronous ExpectMsg calls inside AwaitAssertAsync become FishForMessageAsync with a 5 s bound, because both probes also receive other messages.
  • The test still checks the same three things: Create doesn't throw, LoggingBus reports the slow logger started after the timeout, and the logger then receives log events.

An alternative was capturing the Debug with a LogFilterSetup. It wouldn't work here: the filter is only consulted by StandardOutLogger, and this spec replaces that with XUnitOutLogger.

Verification (local)

  • LoggerStartupSpec passes 6/6, five runs in a row, about 2 s faster than before.

…d 1 s delay

ActorSystem_should_start_with_loggers_timing_out failed on a 2-vCPU Windows
agent: the test subscribes its probe to the EventStream after
ActorSystem.Create returns, but on a starved agent the slow logger's 1 s
delay elapsed first and LoggingBus published its one-shot "Logger ...
started" Debug 1 ms before the subscription existed. The EventStream
doesn't replay, so the sync ExpectMsg<Debug> ate the whole AwaitAssert
budget.

SlowLoggerActor now answers InitializeLogger only when the test opens a
gate, after it has subscribed. The gate is shut for all of Create, so the
logger still always misses the 100 ms logger-startup-timeout - which is
what the test is about - and the started Debug can no longer be published
before anyone is listening. The two sync ExpectMsg-inside-AwaitAssert
checks become FishForMessageAsync, since both probes also receive other
messages.

@Aaronontheweb Aaronontheweb left a comment

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@Aaronontheweb Aaronontheweb left a comment

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

more deterministic than the previous Task.Delay solution - LGTM

@Aaronontheweb
Aaronontheweb merged commit ef7f9c4 into akkadotnet:dev Sep 24, 2026
15 checks passed
@Aaronontheweb
Aaronontheweb deleted the fix/loggerstartupspec-subscribe-race branch September 24, 2026 13:23
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