Fix LocalScriptService: drain async stream readers in CompleteScript/CancelScript
Summary
- Production fix for the timing race PR #273 worked around with
Start-Sleep 1s/2sprefixes across 13 tests -
CompleteScriptandCancelScriptnow always callWaitForExit()(no-arg) after the timed wait, draining .NET'sAsyncStreamReadercallbacks before reading logs - New unit test
CompleteScript_FlushesAsyncStreamReaders_FastExitScript_OutputCapturedruns 5 iterations of fast-exit script — pre-fix would intermittently drop output; post-fix deterministic - 1415/1415 unit tests pass locally
The race
Production code already documented the symptom in SequencedLogWriter.Append's _disposed-late-callback guard:
"Late-OutputDataReceived race: .NET's AsyncStreamReader can dispatch callbacks AFTER WaitForExit returned true... Silent no-op here loses the late line — the same outcome as if the callback had fired one millisecond later when the stream was fully closed — but keeps the host alive."
This PR addresses the root cause:
1. Script writes one line + exits within 50ms
2. CompleteScript called; HasExited=true
→ WaitForExit(timeout) branch SKIPPED (it's gated on !HasExited)
3. ReadLogs reads disk
→ AsyncStreamReader callback hasn't fired yet → log file empty
4. CompleteScript returns ExitCode=0 + empty Logs
5. Late callback fires AFTER LogWriter.Dispose()
→ silently dropped by SequencedLogWriter.Append's _disposed guard
The fix
Per .NET docs: WaitForExit(timeout) (the bool overload) does NOT wait for async readers. Only WaitForExit() (no-arg) flushes async event handlers.
// Pre-fix
if (!running.Process.HasExited)
running.Process.WaitForExit(TimeSpan.FromSeconds(30));
var logs = ReadLogs(running, ...);
// Post-fix
if (!running.Process.HasExited)
running.Process.WaitForExit(TimeSpan.FromSeconds(30));
// ALWAYS drain async stream readers — even if HasExited was already true
// when this method was called. WaitForExit() (no-arg) is fast on an
// already-exited process (sub-millisecond for tiny output).
running.Process.WaitForExit();
var logs = ReadLogs(running, ...);
Two callsites fixed:
-
CompleteScript(line 563+) — primary fix; final-log read path -
CancelScript(line 670+) — same race afterKill; bounded by a 5sWaitForExit(timeout)before the no-arg flush so a stuck zombie doesn't deadlock cancel
Why this matters beyond test stability
The race isn't just a test flake — it's a real production bug. Operators running fast scripts (echo done && exit) silently lose output in their deployment task logs. The drop happens at the late-callback guard, which keeps the agent alive but means the operator sees "Task succeeded" with empty stdout when a debug echo had been emitted.
Follow-up opportunity (NOT in this PR)
After this lands + CI green, the 13 timing-workaround sleeps in TentacleDeployE2ETests + TentacleLinuxDeployE2ETests can be removed (Round 11 — back to bare Echo). Total CI time savings: ~30s per Windows runner, ~25s per Linux runner. Will be a separate cleanup PR.
Test plan
-
dotnet build— 0 errors -
dotnet test tests/Squid.Tentacle.Tests— 1415/1415 passing -
CI Tests workflow green (Squid Tentacle Tests + Calamari + Integration + UnitTests) -
CI Tentacle Linux E2E— all 70 tests still green -
CI Tentacle Windows E2E— all 98 tests still green; especially the timing-sensitive ones (Listening_PlainOutputVariable, Listening_EchoScript, Listening_ConcurrentDispatches) which should now pass even with workaround sleeps still in place -
CI run consistency check: re-run the workflow 2-3 times to confirm previously-flaky tests no longer flake