Joseph Doherty
5962cc3d41
The proto comment, VirtualTags.md and CLAUDE.md said the soft deadline measures the script's own execution and that starvation never counts. Only the time before the run STARTS is excluded; from the start it is wall-clock time, as in process, so a GC pause or a starved / suspended worker during the run still counts. A mid-run freeze test is not added: it races the script's own return against the watchdog's notice; documented as not covered. Also documents F2 (late notice cancels and counts), F3 (progress ceiling, killed_unresponsive) and F5 (answer = stalled | retrigger).
493 lines
28 KiB
C#
493 lines
28 KiB
C#
using System.Diagnostics;
|
|
using System.Runtime.InteropServices;
|
|
using System.Security.Cryptography;
|
|
using System.Text;
|
|
using Serilog;
|
|
using Shouldly;
|
|
using Xunit;
|
|
using ZB.MOM.WW.OtOpcUa.Core.Scripting;
|
|
using ZB.MOM.WW.OtOpcUa.Core.Scripting.OutOfProcess;
|
|
using ZB.MOM.WW.OtOpcUa.Core.Scripting.Protocol.V1;
|
|
|
|
namespace ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests;
|
|
|
|
/// <summary>
|
|
/// lmxopcua#827: the soft deadline T starts when an evaluation thread starts the run — the worker runs that clock —
|
|
/// so the pipe round trip and the time a starved worker takes to START the run no longer count against the script.
|
|
/// From the start it is wall-clock time, as in process: a pause DURING the run still counts, and is not tested
|
|
/// here (a mid-run freeze races the script's own return against the watchdog's notice). The host keeps a transport deadline (T + G from submit) and reports passing
|
|
/// it as a runner fault (<see cref="ScriptRunOutcome.WorkerUnresponsiveReason"/>, BadResourceUnavailable), never as a
|
|
/// script timeout. The starved worker is made real here: its process is suspended (SIGSTOP / NtSuspendProcess)
|
|
/// while a trivial script is submitted.
|
|
/// </summary>
|
|
[Collection(ScriptWorkerCollection.Name)]
|
|
[Trait("Category", "ScriptWorker")]
|
|
public sealed class WorkerSoftClockTests
|
|
{
|
|
private const string Trivial = "return 7;";
|
|
private const string Runaway = "while (true) { }";
|
|
|
|
private static CancellationToken Ct => TestContext.Current.CancellationToken;
|
|
|
|
/// <summary>
|
|
/// A runner whose worker heartbeats every 2 s, so the host's silence kill (3 intervals) stays well clear of the
|
|
/// suspensions below: what is measured is the deadline, not the heartbeat monitor.
|
|
/// </summary>
|
|
private static OutOfProcessScriptRunner Runner(TimeSpan hardGrace, ILogger? log = null)
|
|
=> new(Scripts.Options(hardGrace: hardGrace, quarantineAfterKills: 1), log ?? new LoggerConfiguration().CreateLogger(), null,
|
|
heartbeatInterval: TimeSpan.FromSeconds(2), loadTimeout: TimeSpan.FromSeconds(60));
|
|
|
|
private static async Task<WorkerConnection> WarmAsync(OutOfProcessScriptRunner runner, string key)
|
|
{
|
|
var warm = await runner.RunAsync(Scripts.Vt(key, Trivial, TimeSpan.FromSeconds(30)), Ct);
|
|
warm.Status.ShouldBe(ScriptRunStatus.Ok, warm.Reason);
|
|
var worker = runner.Shards[0].Current.ShouldNotBeNull();
|
|
worker.WorkerSoftClock.ShouldBeTrue("the worker negotiated the soft clock");
|
|
return worker;
|
|
}
|
|
|
|
/// <summary>
|
|
/// The issue's headline: a worker that cannot be scheduled for longer than T, but shorter than the transport
|
|
/// deadline, answers a trivial script with its value. Before #827 the host's clock, started at submit, answered
|
|
/// <c>script timed out after 0.3s</c> for <c>return 7;</c>.
|
|
/// </summary>
|
|
[Fact]
|
|
public async Task A_worker_stalled_for_longer_than_T_still_answers_a_trivial_script_with_its_value()
|
|
{
|
|
var softT = TimeSpan.FromMilliseconds(300);
|
|
await using var runner = Runner(hardGrace: TimeSpan.FromSeconds(3));
|
|
var worker = await WarmAsync(runner, "trivial");
|
|
|
|
Task<ScriptRunOutcome> run;
|
|
using (ProcessFreezer.Freeze(worker.Pid))
|
|
{
|
|
run = runner.RunAsync(Scripts.Vt("trivial", Trivial, softT), Ct);
|
|
await Task.Delay(softT * 4, Ct); // 1.2 s: well past T on the host's clock
|
|
run.IsCompleted.ShouldBeFalse("nothing can answer while the worker is suspended");
|
|
}
|
|
|
|
var outcome = await run.WaitAsync(TimeSpan.FromSeconds(30), Ct);
|
|
outcome.Status.ShouldBe(ScriptRunStatus.Ok, outcome.Reason);
|
|
outcome.Value.ShouldBe(7);
|
|
runner.Shards[0].Current.ShouldNotBeNull().Pid.ShouldBe(worker.Pid, "a stall is not a deadline kill");
|
|
runner.QuarantinedKeys(ScriptContextKind.VirtualTag).ShouldBeEmpty();
|
|
}
|
|
|
|
/// <summary>
|
|
/// A stall past the transport deadline (T + G) is the runner's fault: the caller gets
|
|
/// <see cref="ScriptRunOutcome.WorkerUnresponsiveReason"/> as <see cref="ScriptRunStatus.Unavailable"/> (published
|
|
/// BadResourceUnavailable) with a recovery that completes when the worker answers; a re-trigger meanwhile is the
|
|
/// runner's fault too (not "previous run still running"); the worker is not killed and the key is not struck.
|
|
/// Before #827 this was a script timeout at T and a deadline kill at T + G that struck the key — with
|
|
/// QuarantineAfterKills = 1, a quarantine for <c>return 7;</c>.
|
|
/// </summary>
|
|
[Fact]
|
|
public async Task A_worker_stalled_past_the_transport_deadline_is_a_runner_fault_and_nothing_is_struck()
|
|
{
|
|
var softT = TimeSpan.FromMilliseconds(200);
|
|
var grace = TimeSpan.FromMilliseconds(400);
|
|
await using var runner = Runner(grace);
|
|
var worker = await WarmAsync(runner, "trivial");
|
|
// Review F5: both answers are counted (otopcua.script.ipc.timeouts, answer = stalled | retrigger).
|
|
var answers = new System.Collections.Concurrent.ConcurrentQueue<string>();
|
|
using var listener = new System.Diagnostics.Metrics.MeterListener();
|
|
listener.InstrumentPublished = (instrument, l) =>
|
|
{
|
|
if (instrument.Name == "otopcua.script.ipc.timeouts") l.EnableMeasurementEvents(instrument);
|
|
};
|
|
listener.SetMeasurementEventCallback<long>((_, _, tags, _) =>
|
|
{
|
|
foreach (var tag in tags)
|
|
if (tag.Key == "answer") answers.Enqueue((string)tag.Value!);
|
|
});
|
|
listener.Start();
|
|
|
|
ScriptRunOutcome stalled, retriggered;
|
|
using (ProcessFreezer.Freeze(worker.Pid))
|
|
{
|
|
stalled = await runner.RunAsync(Scripts.Vt("trivial", Trivial, softT), Ct).WaitAsync(TimeSpan.FromSeconds(10), Ct);
|
|
retriggered = await runner.RunAsync(Scripts.Vt("trivial", Trivial, softT), Ct).WaitAsync(TimeSpan.FromSeconds(10), Ct);
|
|
stalled.Recovery.ShouldNotBeNull().IsCompleted.ShouldBeFalse("the worker has not answered yet");
|
|
}
|
|
|
|
stalled.Status.ShouldBe(ScriptRunStatus.Unavailable, stalled.Reason);
|
|
stalled.Reason.ShouldBe(ScriptRunOutcome.WorkerUnresponsiveReason);
|
|
retriggered.Status.ShouldBe(ScriptRunStatus.Unavailable, retriggered.Reason);
|
|
retriggered.Reason.ShouldBe(ScriptRunOutcome.WorkerUnresponsiveReason);
|
|
stalled.ToVirtualTagEvalResult().StatusCode.ShouldBe(Commons.OpcUa.OpcUaStatus.BadResourceUnavailable);
|
|
answers.ToArray().ShouldBe(["stalled", "retrigger"], ignoreOrder: true);
|
|
|
|
await stalled.Recovery!.WaitAsync(TimeSpan.FromSeconds(30), Ct);
|
|
var next = await runner.RunAsync(Scripts.Vt("trivial", Trivial, softT), Ct);
|
|
next.Status.ShouldBe(ScriptRunStatus.Ok, next.Reason);
|
|
next.Value.ShouldBe(7);
|
|
runner.Shards[0].Current.ShouldNotBeNull().Pid.ShouldBe(worker.Pid, "a stall is not a deadline kill");
|
|
runner.QuarantinedKeys(ScriptContextKind.VirtualTag).ShouldBeEmpty();
|
|
}
|
|
|
|
/// <summary>
|
|
/// The other side of the contract is unchanged: a script that really runs past T is answered at T from its own
|
|
/// start and killed G after that, even with the worker stalled before it started. Positive control for the two
|
|
/// tests above — they would also pass if the runner simply never timed anything out.
|
|
/// </summary>
|
|
[Fact]
|
|
public async Task A_runaway_that_starts_late_is_still_timed_out_at_T_from_its_start_and_killed_at_G()
|
|
{
|
|
var softT = TimeSpan.FromMilliseconds(300);
|
|
var grace = TimeSpan.FromMilliseconds(600);
|
|
var stall = TimeSpan.FromMilliseconds(500);
|
|
await using var runner = Runner(grace);
|
|
var worker = await WarmAsync(runner, "warm");
|
|
var load = await runner.RunAsync(Scripts.Vt("runaway", "return 0;", TimeSpan.FromSeconds(30)), Ct);
|
|
load.Status.ShouldBe(ScriptRunStatus.Ok, load.Reason);
|
|
|
|
var sw = Stopwatch.StartNew();
|
|
Task<ScriptRunOutcome> run;
|
|
using (ProcessFreezer.Freeze(worker.Pid))
|
|
{
|
|
run = runner.RunAsync(Scripts.Vt("runaway", Runaway, softT), Ct);
|
|
await Task.Delay(stall, Ct);
|
|
}
|
|
var thawed = sw.Elapsed;
|
|
var outcome = await run.WaitAsync(TimeSpan.FromSeconds(30), Ct);
|
|
var answered = sw.Elapsed;
|
|
|
|
outcome.Status.ShouldBe(ScriptRunStatus.Failed);
|
|
outcome.Reason.ShouldNotBeNull().ShouldStartWith("script timed out after ");
|
|
(answered - thawed).ShouldBeGreaterThanOrEqualTo(softT - TimeSpan.FromMilliseconds(50), "T counts from the run's start, after the stall");
|
|
|
|
var exit = await worker.Exited.WaitAsync(TimeSpan.FromSeconds(30), Ct);
|
|
exit.Reason.ShouldBe(WorkerExitReason.KilledDeadline);
|
|
exit.CulpritKey.ShouldBe(InProcessScriptRunner.ScopedKey(ScriptContextKind.VirtualTag, "runaway"));
|
|
(sw.Elapsed - thawed).ShouldBeGreaterThanOrEqualTo(softT + grace - TimeSpan.FromMilliseconds(50), "G counts from the soft deadline");
|
|
}
|
|
|
|
/// <summary>
|
|
/// Shadow (lmxopcua#780 P2) compares the shadow pool with the published in-process result; a starved worker used to
|
|
/// show up there as a script mismatch (published Ok, shadow "timed out") and skew the census for the OutOfProcess
|
|
/// flip. Now a stall shorter than the transport deadline is a match, and a longer one is <c>shadow_unavailable</c>
|
|
/// — never a mismatch — including the re-trigger that finds the stalled run still holding its slot.
|
|
/// </summary>
|
|
[Fact]
|
|
public async Task In_Shadow_a_stalled_worker_is_a_match_or_shadow_unavailable_never_a_mismatch()
|
|
{
|
|
var softT = TimeSpan.FromMilliseconds(300);
|
|
var grace = TimeSpan.FromSeconds(1);
|
|
var options = Scripts.Options(hardGrace: grace, quarantineAfterKills: 1);
|
|
options.Runner = ScriptRunnerMode.Shadow;
|
|
await using var pool = Runner(grace);
|
|
using var shadow = new ShadowScriptRunner(pool, options, new LoggerConfiguration().CreateLogger());
|
|
var worker = await WarmAsync(pool, "trivial");
|
|
var published = ScriptRunOutcome.Ok(7);
|
|
|
|
// Stall past T, short of T + G: compared, and a match.
|
|
using (ProcessFreezer.Freeze(worker.Pid))
|
|
{
|
|
shadow.Mirror(Scripts.Vt("trivial", Trivial, softT), published);
|
|
await Task.Delay(TimeSpan.FromMilliseconds(900), Ct);
|
|
}
|
|
(await shadow.WaitIdleAsync(TimeSpan.FromSeconds(30))).ShouldBeTrue();
|
|
shadow.Stats().Matched.ShouldBe(1, Summary(shadow));
|
|
|
|
// Stall past T + G: not compared. The second mirror arrives while the first still holds the key's slot.
|
|
using (ProcessFreezer.Freeze(worker.Pid))
|
|
{
|
|
shadow.Mirror(Scripts.Vt("trivial", Trivial, softT), published);
|
|
await Scripts.Eventually(() => shadow.Stats().ShadowUnavailable == 1, TimeSpan.FromSeconds(10), "the transport deadline");
|
|
shadow.Mirror(Scripts.Vt("trivial", Trivial, softT), published);
|
|
await Scripts.Eventually(() => shadow.Stats().ShadowUnavailable == 2, TimeSpan.FromSeconds(10), "the stalled re-trigger");
|
|
}
|
|
(await shadow.WaitIdleAsync(TimeSpan.FromSeconds(30))).ShouldBeTrue();
|
|
|
|
var stats = shadow.Stats();
|
|
stats.Mismatched.ShouldBe(0, Summary(shadow));
|
|
stats.ShadowUnavailable.ShouldBe(2, Summary(shadow));
|
|
stats.Matched.ShouldBe(1);
|
|
pool.Shards[0].Current.ShouldNotBeNull().Pid.ShouldBe(worker.Pid);
|
|
}
|
|
|
|
/// <summary>
|
|
/// Protocol compatibility: the soft clock is negotiated (<c>Hello.worker_soft_clock</c> → <c>Ready.worker_soft_clock</c>).
|
|
/// A host that does not ask for it keeps the pre-#827 contract — the soft deadline is the host's, from submit,
|
|
/// and the worker sends no soft notices — and a runaway is still answered at T and killed at T + G.
|
|
/// </summary>
|
|
[Theory]
|
|
[InlineData(true)]
|
|
[InlineData(false)]
|
|
public async Task The_soft_clock_is_negotiated_and_both_clocks_enforce_T_and_G(bool workerSoftClock)
|
|
{
|
|
var spec = new WorkerLaunchSpec("t", OutOfProcessScriptRunner.ResolveWorkerPath(new ScriptWorkerOptions { ExecutablePath = Scripts.WorkerUnderTest }),
|
|
256L * 1024 * 1024, EvalThreads: 2, HardGrace: TimeSpan.FromSeconds(1), HeartbeatInterval: TimeSpan.FromSeconds(1),
|
|
HandshakeTimeout: TimeSpan.FromSeconds(15), WorkerSoftClock: workerSoftClock);
|
|
var connection = await WorkerConnection.StartAsync(spec, new LoggerConfiguration().CreateLogger(), _ => { }, _ => { }, Ct);
|
|
await using var _ = connection;
|
|
connection.WorkerSoftClock.ShouldBe(workerSoftClock);
|
|
|
|
var entry = await connection.EnsureLoadedAsync("k", ContextKind.VirtualTag, Runaway,
|
|
SHA256.HashData(Encoding.UTF8.GetBytes(Runaway)), []).WaitAsync(TimeSpan.FromSeconds(60), Ct);
|
|
entry.Outcome.ShouldNotBeNull().Ok.ShouldBeTrue();
|
|
|
|
var softT = TimeSpan.FromMilliseconds(300);
|
|
var grace = TimeSpan.FromMilliseconds(500);
|
|
var sw = Stopwatch.StartNew();
|
|
var pending = connection.Submit("k",
|
|
new EvalRequest { Key = "k", SoftTimeoutMs = (uint)softT.TotalMilliseconds, HardGraceMs = (uint)grace.TotalMilliseconds, NowUtcTicks = DateTime.UtcNow.Ticks },
|
|
softT, grace, null);
|
|
(await pending.Outcome.WaitAsync(TimeSpan.FromSeconds(10), Ct)).ShouldBeSameAs(PendingEval.SoftTimedOut);
|
|
sw.Elapsed.ShouldBeGreaterThanOrEqualTo(softT - TimeSpan.FromMilliseconds(20));
|
|
connection.Cancel(pending);
|
|
|
|
var exit = await connection.Exited.WaitAsync(TimeSpan.FromSeconds(10), Ct);
|
|
exit.Reason.ShouldBe(WorkerExitReason.KilledDeadline);
|
|
sw.Elapsed.ShouldBeGreaterThanOrEqualTo(softT + grace - TimeSpan.FromMilliseconds(50));
|
|
}
|
|
|
|
// ---------------------------------------------------------------- review findings (#827)
|
|
|
|
/// <summary>
|
|
/// Review F1: the soft notice is handled on the pipe READER, and the caller's resumption is the caller's code. It
|
|
/// must go through the result dispatcher like a result does: a continuation that blocks for 1.5 s must not hold up
|
|
/// the reader, or the next heartbeats sit unread and a healthy worker is killed for silence (300 ms here). Before
|
|
/// the fix the continuation ran inline on the reader and the worker was killed (KilledHeartbeat).
|
|
/// </summary>
|
|
[Fact]
|
|
public async Task A_slow_continuation_of_a_soft_timeout_does_not_stall_the_reader()
|
|
{
|
|
var heartbeat = TimeSpan.FromMilliseconds(100);
|
|
var spec = new WorkerLaunchSpec("t", OutOfProcessScriptRunner.ResolveWorkerPath(new ScriptWorkerOptions { ExecutablePath = Scripts.WorkerUnderTest }),
|
|
256L * 1024 * 1024, EvalThreads: 2, HardGrace: TimeSpan.FromSeconds(60), HeartbeatInterval: heartbeat,
|
|
HandshakeTimeout: TimeSpan.FromSeconds(15), HeartbeatSilenceLimit: TimeSpan.FromSeconds(30));
|
|
var connection = await WorkerConnection.StartAsync(spec, new LoggerConfiguration().CreateLogger(), _ => { }, _ => { }, Ct);
|
|
await using var _ = connection;
|
|
var entry = await connection.EnsureLoadedAsync("k", ContextKind.VirtualTag, Runaway,
|
|
SHA256.HashData(Encoding.UTF8.GetBytes(Runaway)), []).WaitAsync(TimeSpan.FromSeconds(60), Ct);
|
|
entry.Outcome.ShouldNotBeNull().Ok.ShouldBeTrue();
|
|
connection.SilenceLimit = heartbeat * 3; // armed only once the cold start is over (see SupervisionTests)
|
|
|
|
var softT = TimeSpan.FromMilliseconds(200);
|
|
var pending = connection.Submit("k",
|
|
new EvalRequest { Key = "k", SoftTimeoutMs = (uint)softT.TotalMilliseconds, HardGraceMs = 60_000, NowUtcTicks = DateTime.UtcNow.Ticks },
|
|
softT, TimeSpan.FromSeconds(60), null);
|
|
string? resumedOn = null;
|
|
var slowConsumer = pending.Outcome.ContinueWith(t =>
|
|
{
|
|
resumedOn = Thread.CurrentThread.Name;
|
|
t.Result.ShouldBeSameAs(PendingEval.SoftTimedOut);
|
|
Thread.Sleep(1_500);
|
|
}, CancellationToken.None, TaskContinuationOptions.ExecuteSynchronously, TaskScheduler.Default);
|
|
|
|
await slowConsumer.WaitAsync(TimeSpan.FromSeconds(10), Ct);
|
|
resumedOn.ShouldBe("ScriptWorker[t].Results", "the caller resumes on the dispatcher, never on the reader");
|
|
connection.Exited.IsCompleted.ShouldBeFalse("the reader kept reading heartbeats while the consumer was slow");
|
|
connection.IsAlive.ShouldBeTrue();
|
|
}
|
|
|
|
/// <summary>
|
|
/// Review F2: a stall past T + G answers "worker unresponsive"; when the worker then runs the script and it really
|
|
/// overruns T, the late soft notice must still cancel its token — a polling script ends itself instead of the whole
|
|
/// worker being killed G later — and the run counts as a timeout (QuarantineAfterConsecutiveTimeouts = 1 here).
|
|
/// Before the fix nobody sent the Cancel: the worker was killed at notice + G (KilledDeadline, a kill strike).
|
|
/// </summary>
|
|
[Fact]
|
|
public async Task A_slow_script_whose_notice_arrives_after_the_transport_deadline_is_cancelled_and_counted_not_killed()
|
|
{
|
|
var softT = TimeSpan.FromMilliseconds(200);
|
|
var grace = TimeSpan.FromMilliseconds(400);
|
|
var options = Scripts.Options(hardGrace: grace, quarantineAfterKills: 1);
|
|
options.QuarantineAfterConsecutiveTimeouts = 1;
|
|
await using var runner = new OutOfProcessScriptRunner(options, new LoggerConfiguration().CreateLogger(), null,
|
|
heartbeatInterval: TimeSpan.FromSeconds(2), loadTimeout: TimeSpan.FromSeconds(60));
|
|
const string polite = "if ((int)ctx.GetTag(\"spin\").Value == 1) { while (!ctx.CancellationToken.IsCancellationRequested) { } } return 1;";
|
|
(await runner.RunAsync(Scripts.Vt("polite", polite, TimeSpan.FromSeconds(30), Scripts.Input("spin", 0)), Ct)).Value.ShouldBe(1);
|
|
var worker = runner.Shards[0].Current.ShouldNotBeNull();
|
|
|
|
ScriptRunOutcome stalled;
|
|
using (ProcessFreezer.Freeze(worker.Pid))
|
|
{
|
|
stalled = await runner.RunAsync(Scripts.Vt("polite", polite, softT, Scripts.Input("spin", 1)), Ct).WaitAsync(TimeSpan.FromSeconds(10), Ct);
|
|
}
|
|
stalled.Reason.ShouldBe(ScriptRunOutcome.WorkerUnresponsiveReason);
|
|
|
|
// Thawed: the script starts, spins past T, the late notice cancels it and it returns. The worker survives G.
|
|
await stalled.Recovery.ShouldNotBeNull().WaitAsync(TimeSpan.FromSeconds(10), Ct);
|
|
await Task.Delay(softT + grace + TimeSpan.FromMilliseconds(500), Ct);
|
|
worker.IsAlive.ShouldBeTrue("a cancelled polling script must not cost its worker");
|
|
runner.Shards[0].Current.ShouldNotBeNull().Pid.ShouldBe(worker.Pid);
|
|
|
|
// …and it counted as the timeout it was (threshold 1), not as a kill.
|
|
await Scripts.Eventually(() => runner.QuarantinedKeys(ScriptContextKind.VirtualTag).Count == 1, TimeSpan.FromSeconds(5), "the timeout quarantine");
|
|
var refused = await runner.RunAsync(Scripts.Vt("polite", polite, softT, Scripts.Input("spin", 0)), Ct);
|
|
refused.Reason.ShouldNotBeNull().ShouldContain("timed out");
|
|
refused.Reason.ShouldNotContain("hard deadline");
|
|
}
|
|
|
|
/// <summary>
|
|
/// Review F3: the host keeps its own bound. A worker that heartbeats but never sends a soft notice (a bug, or a
|
|
/// compromised worker — simulated by the host dropping its notices) used to hold the run, the key's slot and the
|
|
/// tag's BadResourceUnavailable forever: the transport deadline answers the caller once and the kill G is armed
|
|
/// only by a notice. Now no progress for the ceiling, with evaluations outstanding, kills the worker
|
|
/// (<see cref="WorkerExitReason.KilledUnresponsive"/>, no culprit) and the run completes. G is 60 s here, so the
|
|
/// worker's own fail-fast watchdog (notice + G + 0.5 s) cannot be what ends it.
|
|
/// </summary>
|
|
[Fact]
|
|
public async Task A_worker_that_heartbeats_but_never_reports_progress_is_killed_at_the_host_ceiling()
|
|
{
|
|
var spec = new WorkerLaunchSpec("t", OutOfProcessScriptRunner.ResolveWorkerPath(new ScriptWorkerOptions { ExecutablePath = Scripts.WorkerUnderTest }),
|
|
256L * 1024 * 1024, EvalThreads: 2, HardGrace: TimeSpan.FromSeconds(60), HeartbeatInterval: TimeSpan.FromMilliseconds(200),
|
|
HandshakeTimeout: TimeSpan.FromSeconds(15), HeartbeatSilenceLimit: TimeSpan.FromSeconds(30));
|
|
var connection = await WorkerConnection.StartAsync(spec, new LoggerConfiguration().CreateLogger(), _ => { }, _ => { }, Ct);
|
|
await using var _ = connection;
|
|
var entry = await connection.EnsureLoadedAsync("k", ContextKind.VirtualTag, Runaway,
|
|
SHA256.HashData(Encoding.UTF8.GetBytes(Runaway)), []).WaitAsync(TimeSpan.FromSeconds(60), Ct);
|
|
entry.Outcome.ShouldNotBeNull().Ok.ShouldBeTrue();
|
|
connection.DropSoftNoticesForTest = true;
|
|
connection.ProgressCeilingOverride = TimeSpan.FromSeconds(1.5);
|
|
|
|
var softT = TimeSpan.FromMilliseconds(200);
|
|
var sw = Stopwatch.StartNew();
|
|
var pending = connection.Submit("k",
|
|
new EvalRequest { Key = "k", SoftTimeoutMs = (uint)softT.TotalMilliseconds, HardGraceMs = 60_000, NowUtcTicks = DateTime.UtcNow.Ticks },
|
|
softT, TimeSpan.FromSeconds(60), null);
|
|
|
|
var exit = await connection.Exited.WaitAsync(TimeSpan.FromSeconds(15), Ct);
|
|
exit.Reason.ShouldBe(WorkerExitReason.KilledUnresponsive);
|
|
exit.CulpritKey.ShouldBeNull("nothing says which script, so nothing is struck");
|
|
exit.InFlightKeys.ShouldBe(["k"]);
|
|
sw.Elapsed.ShouldBeGreaterThanOrEqualTo(TimeSpan.FromSeconds(1.4), "not before the ceiling");
|
|
(await pending.Completion.WaitAsync(TimeSpan.FromSeconds(5), Ct)).ShouldBeNull("the run is released");
|
|
}
|
|
|
|
/// <summary>Positive control for the ceiling: the default rule leaves a busy, answering worker alone.</summary>
|
|
[Fact]
|
|
public async Task The_progress_ceiling_leaves_a_worker_that_keeps_answering_alone()
|
|
{
|
|
var spec = new WorkerLaunchSpec("t", OutOfProcessScriptRunner.ResolveWorkerPath(new ScriptWorkerOptions { ExecutablePath = Scripts.WorkerUnderTest }),
|
|
256L * 1024 * 1024, EvalThreads: 1, HardGrace: TimeSpan.FromSeconds(60), HeartbeatInterval: TimeSpan.FromMilliseconds(100),
|
|
HandshakeTimeout: TimeSpan.FromSeconds(15), HeartbeatSilenceLimit: TimeSpan.FromSeconds(30));
|
|
var connection = await WorkerConnection.StartAsync(spec, new LoggerConfiguration().CreateLogger(), _ => { }, _ => { }, Ct);
|
|
await using var _ = connection;
|
|
const string spin = "var end = ctx.Now.AddMilliseconds(150); while (ctx.Now < end) { } return 1;";
|
|
var entry = await connection.EnsureLoadedAsync("k", ContextKind.VirtualTag, spin,
|
|
SHA256.HashData(Encoding.UTF8.GetBytes(spin)), []).WaitAsync(TimeSpan.FromSeconds(60), Ct);
|
|
entry.Outcome.ShouldNotBeNull().Ok.ShouldBeTrue();
|
|
// Ceiling 1 s; 20 runs of 150 ms queued behind one evaluation thread take ~3 s, but each answers.
|
|
connection.ProgressCeilingOverride = TimeSpan.FromSeconds(1);
|
|
var soft = TimeSpan.FromSeconds(30);
|
|
var pendings = connection.SubmitBatch(Enumerable.Range(0, 20).Select(_ => new BatchSubmission("k",
|
|
new EvalRequest { Key = "k", SoftTimeoutMs = 30_000, HardGraceMs = 60_000, NowUtcTicks = DateTime.UtcNow.Ticks },
|
|
soft, TimeSpan.FromSeconds(60), null)).ToArray());
|
|
foreach (var p in pendings) (await p.Completion.WaitAsync(TimeSpan.FromSeconds(30), Ct)).ShouldNotBeNull();
|
|
connection.IsAlive.ShouldBeTrue();
|
|
}
|
|
|
|
// ---------------------------------------------------------------- PendingEval, no process
|
|
|
|
/// <summary>The host side of the worker clock, deterministic: no notice means the transport deadline at T + G.</summary>
|
|
[Fact]
|
|
public async Task Worker_clock_with_no_word_from_the_worker_answers_transport_timed_out_at_T_plus_G_and_never_kills()
|
|
{
|
|
var killed = 0;
|
|
var pending = new PendingEval("k", 1);
|
|
var sw = Stopwatch.StartNew();
|
|
pending.Arm(TimeSpan.FromMilliseconds(100), TimeSpan.FromMilliseconds(200), _ => Interlocked.Increment(ref killed), workerClock: true);
|
|
|
|
(await pending.Outcome.WaitAsync(TimeSpan.FromSeconds(10), Ct)).ShouldBeSameAs(PendingEval.TransportTimedOut);
|
|
sw.Elapsed.ShouldBeGreaterThanOrEqualTo(TimeSpan.FromMilliseconds(280));
|
|
await Task.Delay(500, Ct);
|
|
killed.ShouldBe(0, "a late worker is not the script's fault");
|
|
|
|
// A soft notice after the transport answer still arms the kill: the script itself ran for T.
|
|
pending.SoftExpired();
|
|
await Scripts.Eventually(() => Volatile.Read(ref killed) == 1, TimeSpan.FromSeconds(10), "the kill G after the soft notice");
|
|
}
|
|
|
|
/// <summary>The soft notice answers the caller and arms the kill G later; a result before then cancels it.</summary>
|
|
[Fact]
|
|
public async Task Worker_clock_soft_notice_answers_soft_timed_out_and_arms_the_kill_G_later()
|
|
{
|
|
var killed = 0;
|
|
var pending = new PendingEval("k", 1);
|
|
pending.Arm(TimeSpan.FromSeconds(30), TimeSpan.FromMilliseconds(300), _ => Interlocked.Increment(ref killed), workerClock: true);
|
|
pending.Outcome.IsCompleted.ShouldBeFalse();
|
|
|
|
var sw = Stopwatch.StartNew();
|
|
pending.SoftExpired();
|
|
(await pending.Outcome.WaitAsync(TimeSpan.FromSeconds(1), Ct)).ShouldBeSameAs(PendingEval.SoftTimedOut);
|
|
await Scripts.Eventually(() => Volatile.Read(ref killed) == 1, TimeSpan.FromSeconds(10), "the kill");
|
|
sw.Elapsed.ShouldBeGreaterThanOrEqualTo(TimeSpan.FromMilliseconds(280));
|
|
|
|
var answered = new PendingEval("k2", 2);
|
|
answered.Arm(TimeSpan.FromSeconds(30), TimeSpan.FromMilliseconds(100), _ => Interlocked.Increment(ref killed), workerClock: true);
|
|
answered.SoftExpired();
|
|
answered.Complete(new EvalResult { EvalId = 2 });
|
|
await Task.Delay(400, Ct);
|
|
killed.ShouldBe(1, "a run that answered inside G is not killed");
|
|
}
|
|
|
|
/// <summary>Under the host clock a soft notice means nothing (a worker that did not negotiate it cannot send one).</summary>
|
|
[Fact]
|
|
public void Host_clock_ignores_a_soft_notice()
|
|
{
|
|
var pending = new PendingEval("k", 1);
|
|
pending.Arm(TimeSpan.FromSeconds(30), TimeSpan.FromSeconds(30), _ => { }, workerClock: false);
|
|
pending.SoftExpired();
|
|
pending.Outcome.IsCompleted.ShouldBeFalse();
|
|
pending.Complete(null);
|
|
}
|
|
|
|
private static string Summary(ShadowScriptRunner shadow)
|
|
=> $"{shadow.Stats()}; " + string.Join("; ", shadow.Mismatches.Select(m => $"{m.Key}: {m.LastReason} — {m.LastSummary}"));
|
|
}
|
|
|
|
/// <summary>Suspends a process (SIGSTOP, or NtSuspendProcess on Windows) until disposed.</summary>
|
|
internal sealed class ProcessFreezer : IDisposable
|
|
{
|
|
private readonly int _pid;
|
|
private int _thawed;
|
|
|
|
private ProcessFreezer(int pid)
|
|
{
|
|
_pid = pid;
|
|
Signal(pid, stop: true);
|
|
}
|
|
|
|
public static ProcessFreezer Freeze(int pid) => new(pid);
|
|
|
|
public void Dispose()
|
|
{
|
|
if (Interlocked.Exchange(ref _thawed, 1) == 0) Signal(_pid, stop: false);
|
|
}
|
|
|
|
private static void Signal(int pid, bool stop)
|
|
{
|
|
if (OperatingSystem.IsWindows())
|
|
{
|
|
using var process = Process.GetProcessById(pid);
|
|
var status = stop ? NtSuspendProcess(process.Handle) : NtResumeProcess(process.Handle);
|
|
status.ShouldBe(0, $"Nt{(stop ? "Suspend" : "Resume")}Process");
|
|
return;
|
|
}
|
|
// libc kill(2), not the kill(1) command: a child process's exit is observed through the same SIGCHLD
|
|
// handling that the suspended worker (another child of this process) just disturbed, and WaitForExit was
|
|
// seen to take seconds.
|
|
var signal = stop ? SigStop : SigCont;
|
|
Kill(pid, signal).ShouldBe(0, $"kill({pid}, {signal}): errno {Marshal.GetLastPInvokeError()}");
|
|
}
|
|
|
|
/// <summary>SIGSTOP / SIGCONT: 17 / 19 on macOS (BSD), 19 / 18 on Linux.</summary>
|
|
private static int SigStop => OperatingSystem.IsMacOS() ? 17 : 19;
|
|
|
|
private static int SigCont => OperatingSystem.IsMacOS() ? 19 : 18;
|
|
|
|
#pragma warning disable SYSLIB1054 // DllImport kept: LibraryImport would need AllowUnsafeBlocks for three test-only calls.
|
|
[DllImport("libc", EntryPoint = "kill", SetLastError = true)]
|
|
private static extern int Kill(int pid, int signal);
|
|
|
|
[DllImport("ntdll.dll")]
|
|
private static extern int NtSuspendProcess(IntPtr processHandle);
|
|
|
|
[DllImport("ntdll.dll")]
|
|
private static extern int NtResumeProcess(IntPtr processHandle);
|
|
#pragma warning restore SYSLIB1054
|
|
}
|