Skip to content

Fix LocalScriptService: drain async stream readers in CompleteScript/CancelScript

Placeholder ppxd requested to merge fix/localscriptservice-process-start-race into main

Summary

  • Production fix for the timing race PR #273 worked around with Start-Sleep 1s/2s prefixes across 13 tests
  • CompleteScript and CancelScript now always call WaitForExit() (no-arg) after the timed wait, draining .NET's AsyncStreamReader callbacks before reading logs
  • New unit test CompleteScript_FlushesAsyncStreamReaders_FastExitScript_OutputCaptured runs 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 after Kill; bounded by a 5s WaitForExit(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

🤖 Generated with Claude Code

Merge request reports

Loading