fix(scripting): host progress ceiling kills a worker that heartbeats but never answers (#827 review F3)

With the worker soft clock the host's per-run timer is only the transport
deadline and the kill G is armed by the worker's soft notice, so a worker
whose watchdog never sends one (the design treats the worker as untrusted)
held the run, the key's slot and the tag's BadResourceUnavailable forever;
a deferred run had no host clock at all.

WorkerConnection now tracks evaluation progress (any Results frame, or the
submit that made the worker busy again). The heartbeat monitor kills the
worker when evaluations are outstanding and nothing progressed for
3 x the largest outstanding T + G plus the silence limit:
WorkerExitReason.KilledUnresponsive (metric reason killed_unresponsive), no
culprit, attributed like a heartbeat kill (suspects, no strike on a shard).
A legitimate run has answered or been killed by T + G.

Test seams: ProgressCeilingOverride, DropSoftNoticesForTest. Tests: a worker
whose notices are dropped (G = 60 s, so its own fail-fast cannot end it) is
killed KilledUnresponsive after the 1.5 s ceiling and the run is released
(with the check disabled the test times out); positive control: 20 queued
150 ms runs behind one thread under a 1 s ceiling are all answered.
This commit is contained in:
Joseph Doherty
2026-11-11 02:24:01 -05:00
parent c5dffbd8b8
commit 3f5fdd1d90
4 changed files with 115 additions and 2 deletions
@@ -21,6 +21,12 @@ internal enum WorkerExitReason
/// <summary>The host killed it: no frame for three heartbeat intervals.</summary>
KilledHeartbeat,
/// <summary>
/// The host killed it: it kept heartbeating but answered nothing — no result, no start, no soft-deadline notice —
/// for the progress ceiling while evaluations were outstanding (#827 review F3). Attributed like a heartbeat kill.
/// </summary>
KilledUnresponsive,
/// <summary>The host killed it: a compile did not finish in time (<see cref="WorkerExit.CulpritKey"/>).</summary>
KilledLoadTimeout,
@@ -155,6 +161,12 @@ internal sealed class WorkerConnection : IAsyncDisposable
private int _finished;
private (WorkerExitReason Reason, string? Culprit)? _killedFor;
private long _lastFrameTimestamp;
/// <summary>
/// <see cref="Stopwatch.GetTimestamp"/> of the last evaluation progress — a Results frame of any kind — or of the
/// submit that made the worker busy again. See <see cref="ProgressCeiling"/>.
/// </summary>
private long _lastProgressTimestamp;
private long _nextEvalId;
private long _nextLoadId;
private int _disposed;
@@ -235,6 +247,32 @@ internal sealed class WorkerConnection : IAsyncDisposable
private long _silenceLimitTicks;
/// <summary>
/// The host's own bound on a worker that heartbeats but makes no evaluation progress (#827 review F3). With the
/// worker soft clock the host's per-run timer is only the transport deadline, and the kill G is armed by the
/// worker's soft notice — so a worker whose watchdog never sends one (a bug; the design treats the worker as
/// untrusted) would hold a key's slot, and its tag at BadResourceUnavailable, forever; a deferred run has no host
/// clock at all. So: while evaluations are outstanding and none of them has produced a result, start or soft
/// notice for 3 × the largest outstanding T + G plus the silence limit, the worker is killed
/// (<see cref="WorkerExitReason.KilledUnresponsive"/>, no culprit: attributed like a heartbeat kill, so no key is
/// struck on a shard). A legitimate run never gets near it: by T + G it has answered or been killed. Null = that
/// rule; set = an override (tests).
/// </summary>
internal TimeSpan? ProgressCeilingOverride { get; set; }
/// <summary>Test seam: ignore the worker's soft-deadline notices, as a worker whose watchdog never sends them would.</summary>
internal bool DropSoftNoticesForTest { get; set; }
/// <summary>The progress ceiling now (see <see cref="ProgressCeilingOverride"/>); null = no outstanding deadline.</summary>
private TimeSpan? ProgressCeiling()
{
if (ProgressCeilingOverride is { } fixedCeiling) return fixedCeiling;
var largest = TimeSpan.Zero;
foreach (var (_, pending) in _pending)
if (pending.HardDeadline > largest) largest = pending.HardDeadline;
return largest == TimeSpan.Zero ? null : (largest * 3) + SilenceLimit;
}
/// <summary>Compiles currently outstanding on this worker.</summary>
public int LoadingCount => _loads.Count;
@@ -592,6 +630,7 @@ internal sealed class WorkerConnection : IAsyncDisposable
{
request.EvalId = (ulong)Interlocked.Increment(ref _nextEvalId);
Interlocked.Exchange(ref _lastUsedTimestamp, Stopwatch.GetTimestamp());
if (_pending.IsEmpty) Interlocked.Exchange(ref _lastProgressTimestamp, Stopwatch.GetTimestamp());
var pending = new PendingEval(key, request.EvalId, onFinished, _dispatcher);
if (softTimeout is { } soft) pending.Arm(soft, hardGrace, OnHardDeadline, WorkerSoftClock);
_pending[request.EvalId] = pending;
@@ -617,6 +656,7 @@ internal sealed class WorkerConnection : IAsyncDisposable
var pendings = new PendingEval[items.Count];
var batch = new EvalBatch();
Interlocked.Exchange(ref _lastUsedTimestamp, Stopwatch.GetTimestamp());
if (_pending.IsEmpty) Interlocked.Exchange(ref _lastProgressTimestamp, Stopwatch.GetTimestamp());
for (var i = 0; i < items.Count; i++)
{
var item = items[i];
@@ -800,6 +840,8 @@ internal sealed class WorkerConnection : IAsyncDisposable
switch (frame.BodyCase)
{
case Envelope.BodyOneofCase.Results:
Volatile.Write(ref _lastProgressTimestamp, Stopwatch.GetTimestamp());
if (DropSoftNoticesForTest) frame.Results.SoftExpiredEvalIds.Clear();
// Worker soft clock (lmxopcua#827): the script itself has run for T. Only a worker that agreed to run
// the clock may send these. Before the results: the writer coalesces frames, and a notice the worker
// sent ahead of the same run's result must still answer the caller with its timeout, as in process.
@@ -915,6 +957,17 @@ internal sealed class WorkerConnection : IAsyncDisposable
Kill(WorkerExitReason.KilledHeartbeat, null);
return;
}
if (!_pending.IsEmpty && ProgressCeiling() is { } ceiling)
{
var stuck = Stopwatch.GetElapsedTime(Volatile.Read(ref _lastProgressTimestamp));
if (stuck > ceiling)
{
_log.Warning("ScriptWorker[{Shard}] pid {Pid} has {Count} evaluation(s) outstanding and made no progress for {Stuck} ms (ceiling {Ceiling} ms) while still heartbeating; killing it",
Shard, Pid, _pending.Count, (long)stuck.TotalMilliseconds, (long)ceiling.TotalMilliseconds);
Kill(WorkerExitReason.KilledUnresponsive, null);
return;
}
}
}
}
catch (OperationCanceledException) { }