diff --git a/CHANGELOG.md b/CHANGELOG.md index efc74e6..a4ccb66 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -30,6 +30,13 @@ reconnected. The daemon now forwards the time a request has left, the seat takes its own waits off as well, and a desktop operation is stopped a second before its time runs out, so one queued behind another answers, or fails, in time. +- **A desktop action that runs out of time says so.** An action stopped at its deadline, such as a + `seat_wait` left with less time than its wait after queueing behind a long display change, answered + with a bare "TaskCanceledException: A task was canceled.", which said neither that time ran out nor + whether anything ran. It now fails with `errorCode: "timed_out"` and the time the request had, + and `started: false` and "Nothing was done" when it was still waiting for the desktop, or + `started: true` when it was stopped partway; a read-only action says that nothing changed. A request + whose time ran out before it was even sent also answers `timed_out` with `started: false`. - **Typing keeps pace with the program.** `seat_type` and `anode type` sent characters as fast as Windows took them, so a busy program, such as Chrome editing a long field, could drop and reorder them while the call still reported success. Characters now go out 15 ms apart by default, timed diff --git a/docs/PROTOCOL.md b/docs/PROTOCOL.md index c4c281e..4c4ff4c 100644 --- a/docs/PROTOCOL.md +++ b/docs/PROTOCOL.md @@ -26,6 +26,12 @@ daemon forwards a request with `timeoutMs` set to the time it has left after wai operations on its one connection to the seat host (waits under 100 ms aren't counted), and the seat host takes its own waits off as well. A desktop operation is stopped a second (or an eighth of a shorter time) before that time runs out, so even one cut short answers before its caller gives up. +It fails with `errorCode: "timed_out"`, and `started` says how far it got: `false` when it was still +waiting for the desktop behind an earlier operation and did nothing, `true` when it was stopped +partway and may have done some of its work (one that only reads, such as `desktop.wait`, changed +nothing even then). A request whose time runs out before it is sent at all, in a client's queue or +the daemon's, fails the same way with `started: false`. Once started, operations that bound their own +work by the time, such as `input.text`, report their own failure instead. Limits derived from the time, such as how much one `input.text` may type, shrink with it. Desktop operations additionally require an `agentId` and live `leaseToken`, acquired through diff --git a/docs/TROUBLESHOOTING.md b/docs/TROUBLESHOOTING.md index ab1144b..a20592d 100644 --- a/docs/TROUBLESHOOTING.md +++ b/docs/TROUBLESHOOTING.md @@ -41,9 +41,13 @@ with an ordinary terminal. Only `anode setup` needs administrator approval. ### A command timed out and the viewer is still connected -The timed-out command may have executed. Check the seat before repeating it. Run `anode start` -to reconnect the seat host if the daemon reports it is not ready; Anode can recover that connection -without waiting for the viewer to reconnect. `anode kill` remains available to stop the seat. +The timed-out command may have executed. Check the seat before repeating it. A desktop action that +the seat stopped at its deadline says how far it got: `timed_out` with `started: false` did nothing, +since it was still waiting behind an earlier action; with `started: true` it was stopped partway (one +that only reads, such as `seat_wait`, changed nothing). +Run `anode start` to reconnect the seat host if the daemon reports it is not ready; Anode can +recover that connection without waiting for the viewer to reconnect. `anode kill` remains available +to stop the seat. ### "Remote Desktop host: fDenyTSConnections = 1" diff --git a/src/Anode/Cli/AgentChecks.cs b/src/Anode/Cli/AgentChecks.cs index 0850607..d0e1a93 100644 --- a/src/Anode/Cli/AgentChecks.cs +++ b/src/Anode/Cli/AgentChecks.cs @@ -337,6 +337,76 @@ async Task Hold(JsonObject request, CancellationToken cancel) return "an action queued behind another of its agent's runs in the time its caller has left, and stops before it"; } + /// + /// A desktop action its deadline cuts short answers timed_out with the time it had and whether it started, + /// not a bare "A task was canceled.": one still queued did nothing. A stopping seat still cancels. + /// + public static async Task DeadlineReplies() + { + var entered = Signal(); var finish = Signal(); + var record = new System.Collections.Concurrent.ConcurrentQueue(); + var lease = new DesktopLease(record: record.Enqueue); + int dispatched = 0; + async Task Dispatch(JsonObject request, CancellationToken cancel) + { + Interlocked.Increment(ref dispatched); + if (request.Str("text") == "first") + { + entered.TrySetResult(); + await finish.Task; + return JsonLine.Ok(); + } + await Task.Delay(Timeout.Infinite, cancel); // An action that doesn't size its work by its time. + return JsonLine.Ok(); + } + string token = (await lease.HandleAsync(Lease("A", "acquire"), Dispatch)).Obj("result")!.Str("leaseToken")!; + Task first = lease.HandleAsync(Input("A", token, "first"), Dispatch); + JsonObject queued; + try + { + await entered.Task.WaitAsync(TimeSpan.FromSeconds(2)); + var waiting = Input("A", token, "queued"); + waiting["timeoutMs"] = 800; + queued = await lease.HandleAsync(waiting, Dispatch).WaitAsync(TimeSpan.FromSeconds(5)); + } + finally { finish.TrySetResult(); } + Require((await first.WaitAsync(TimeSpan.FromSeconds(2))).Bool("ok") == true, "the action in front failed"); + Require(dispatched == 1, $"a request that never got the desktop was dispatched ({dispatched} dispatches)"); + Require(queued.Bool("ok") == false && queued.Str("errorCode") == "timed_out" && queued.Bool("started") == false + && queued.Str("error") is { } never && never.Contains("800 ms") && never.Contains("Nothing was done"), + "a request that ran out of time in the queue did not say so: " + queued.ToJsonString()); + + var held = Input("A", token, "held"); + held["timeoutMs"] = 1500; + var stopped = await lease.HandleAsync(held, Dispatch).WaitAsync(TimeSpan.FromSeconds(5)); + Require(stopped.Bool("ok") == false && stopped.Str("errorCode") == "timed_out" && stopped.Bool("started") == true + && stopped.Str("error") is { } partway && partway.Contains("1.5 s") && partway.Contains("may have run"), + "an action stopped partway did not say so: " + stopped.ToJsonString()); + var look = new JsonObject { ["op"] = "desktop.wait", ["agentId"] = "A", ["leaseToken"] = token, ["windowId"] = "w_1", ["textContains"] = "never", ["timeoutMs"] = 1000 }; + var read = await lease.HandleAsync(look, Dispatch).WaitAsync(TimeSpan.FromSeconds(5)); + Require(read.Str("errorCode") == "timed_out" && read.Bool("started") == true && read.Str("error") is { } safe + && safe.Contains("nothing changed") && !safe.Contains("may have run"), "a read-only action stopped partway was said to have acted: " + read.ToJsonString()); + var start = new JsonObject { ["op"] = "exec.start", ["agentId"] = "A", ["leaseToken"] = token, ["path"] = "unused-test-command", ["timeoutMs"] = 1000 }; + var started = await lease.HandleAsync(start, Dispatch).WaitAsync(TimeSpan.FromSeconds(5)); + Require(started.Str("errorCode") == "timed_out" && started.Bool("started") == true && started.Str("error") is { } job + && job.Contains("seat_job action=list"), "a command start cut short didn't point at the job list: " + started.ToJsonString()); + Require(record.Any(line => line == "'input.text' ran out of its 800 ms before it got the desktop") + && record.Any(line => line == "'input.text' ran out of its 1.5 s and was stopped"), "a timeout left no log line: " + string.Join(" | ", record)); + Require((await lease.HandleAsync(Input("A", token, "first"), Dispatch).WaitAsync(TimeSpan.FromSeconds(2))).Bool("ok") == true, + "a timed-out action kept the desktop from the next one"); + + using var stopping = new CancellationTokenSource(); + Task during = lease.HandleAsync(Input("A", token, "held"), Dispatch, stopping.Token); + stopping.Cancel(); + try + { + var reply = await during.WaitAsync(TimeSpan.FromSeconds(2)); + throw new InvalidOperationException("a stopping seat's cancellation was answered as a timeout: " + reply.ToJsonString()); + } + catch (OperationCanceledException) { } + return "an action cut short by its deadline answers timed_out with its time and how far it got: nothing done, nothing changed, a job to find, or input that may have run"; + } + public static async Task Line() { long now = 0; diff --git a/src/Anode/Cli/SelfTest.cs b/src/Anode/Cli/SelfTest.cs index 05435d4..6935b6e 100644 --- a/src/Anode/Cli/SelfTest.cs +++ b/src/Anode/Cli/SelfTest.cs @@ -144,6 +144,7 @@ public static int Run(string[] args) Check(results, "MCP lease client process", () => McpChecks.LeaseClientProcess().GetAwaiter().GetResult()); Check(results, "agent queue and disconnect", () => AgentChecks.QueueAndDisconnect().GetAwaiter().GetResult()); Check(results, "agent queue time", () => AgentChecks.QueueTime().GetAwaiter().GetResult()); + Check(results, "agent deadline replies", () => AgentChecks.DeadlineReplies().GetAwaiter().GetResult()); Check(results, "agent line", () => AgentChecks.Line().GetAwaiter().GetResult()); Check(results, "agent names", () => AgentChecks.Names().GetAwaiter().GetResult()); Check(results, "MCP ownership", () => AgentChecks.McpOwnership().GetAwaiter().GetResult()); diff --git a/src/Anode/Cli/TransportChecks.cs b/src/Anode/Cli/TransportChecks.cs index d138e22..012a2f0 100644 --- a/src/Anode/Cli/TransportChecks.cs +++ b/src/Anode/Cli/TransportChecks.cs @@ -44,7 +44,8 @@ public static async Task QueueDeadline() { await entered.Task.WaitAsync(TimeSpan.FromSeconds(3)); var queued = await client.RequestAsync("queued", timeoutMs: 100).WaitAsync(TimeSpan.FromSeconds(2)); - Require(queued.Bool("ok") == false && queued.Str("error")!.Contains("timed out"), "queued request did not time out"); + Require(queued.Bool("ok") == false && queued.Str("error")!.Contains("timed out") + && queued.Str("errorCode") == "timed_out" && queued.Bool("started") == false, "queued request did not time out as never sent: " + queued.ToJsonString()); Require(!first.IsCompleted && client.IsConnected, "queue timeout interrupted the active request"); } finally { release.TrySetResult(); } @@ -109,7 +110,8 @@ public static async Task ForwardTimeLeft() finally { release.TrySetResult(); } var unsent = await starved.WaitAsync(TimeSpan.FromSeconds(3)); Require((await first.WaitAsync(TimeSpan.FromSeconds(3))).Bool("ok") == true && unsent.Bool("ok") == false - && !given.ContainsKey("starved") && seat.IsConnected, "a request with almost no time left was sent, or cost the connection: " + unsent.ToJsonString()); + && !given.ContainsKey("starved") && seat.IsConnected && unsent.Str("errorCode") == "timed_out" && unsent.Bool("started") == false, + "a request with almost no time left was sent, cost the connection, or didn't say it never started: " + unsent.ToJsonString()); return "the daemon forwards each request with its caller's time left, so time queued behind another isn't counted twice"; } @@ -126,6 +128,8 @@ public static async Task LateReply() ?? throw new InvalidOperationException("could not connect to the test pipe"); var timedOut = await client.RequestAsync("slow", timeoutMs: 100); Require(timedOut.Bool("ok") == false && !client.IsConnected, "timed-out connection stayed reusable"); + // It was sent, so it may have run: it must not claim, as an unsent request does, that it never started. + Require(timedOut["started"] is null, "a request timed out after it was sent claimed it never started: " + timedOut.ToJsonString()); var next = await client.RequestAsync("next", timeoutMs: 4000); Require(next.Bool("ok") == false, "a late reply was accepted as the next result"); using var fresh = await JsonPipeClient.TryConnectAsync(name, 4000) diff --git a/src/Anode/Core/Agents/DesktopLease.cs b/src/Anode/Core/Agents/DesktopLease.cs index 963764f..3a5303c 100644 --- a/src/Anode/Core/Agents/DesktopLease.cs +++ b/src/Anode/Core/Agents/DesktopLease.cs @@ -1,4 +1,5 @@ using System.Diagnostics; +using System.Globalization; using System.Text.Json.Nodes; using Anode.Core.Bridge; @@ -36,7 +37,7 @@ private sealed class Waiter(string agent, string? name, long seen) private long _clientStarted; private bool _active; - /// Receives a line each time the desktop changes hands, for the log. + /// Receives a line for the log each time the desktop changes hands or an action runs out of time. public DesktopLease(Action? invalidateReferences = null, Func? cancelJobs = null, Func? milliseconds = null, Action? record = null, Func? clientAlive = null) { @@ -204,6 +205,28 @@ private JsonObject Manage(JsonObject request) /// internal static int StopAfterMs(int timeoutMs) => Math.Max(1, timeoutMs - Math.Min(1000, timeoutMs / 8)); + /// + /// The failure for a desktop action its deadline cut short. It names the time the request had and says whether + /// the action had started: one still waiting for the desktop did nothing, one stopped partway may have done some, + /// unless it only reads. + /// + private JsonObject TimedOut(string op, int timeoutMs, bool started) + { + string time = timeoutMs < 1000 ? $"{timeoutMs} ms" : (timeoutMs / 1000.0).ToString("0.#", CultureInfo.InvariantCulture) + " s"; + string message = !started + ? $"The request ran out of its {time} while it waited behind an earlier desktop action, so it never started. Nothing was done." + : $"The desktop action ran out of its {time} and was stopped. " + (Mcp.Tools.ReadsOnly(op) + ? "It only reads the desktop, so nothing changed, and it is safe to repeat." + : op == "exec.start" + ? "The command may have started: look for it with seat_job action=list before starting it again." + : "Part of it may have run: observe the desktop before acting again, and don't repeat it unseen."); + _record($"'{op}' ran out of its {time}" + (started ? " and was stopped" : " before it got the desktop")); + var failure = JsonLine.Fail(message); + failure["errorCode"] = "timed_out"; + failure["started"] = started; + return failure; + } + public async Task HandleAsync(JsonObject request, Func> dispatch, CancellationToken cancel = default) { @@ -216,9 +239,13 @@ public async Task HandleAsync(JsonObject request, if (!AgentAccess.RequiresLease(op)) return await dispatch(request, cancel).ConfigureAwait(false); lock (_state) { if (Check(request) is { } error) return error; } + int timeoutMs = request.Int("timeoutMs") ?? 60000; using var deadline = CancellationTokenSource.CreateLinkedTokenSource(cancel); - deadline.CancelAfter(StopAfterMs(request.Int("timeoutMs") ?? 60000)); - await _interaction.WaitAsync(deadline.Token).ConfigureAwait(false); + deadline.CancelAfter(StopAfterMs(timeoutMs)); + // Only the deadline's own cancellation is a timeout; a stopping seat still cancels as before. + bool OutOfTime() => deadline.IsCancellationRequested && !cancel.IsCancellationRequested; + try { await _interaction.WaitAsync(deadline.Token).ConfigureAwait(false); } + catch (OperationCanceledException) when (OutOfTime()) { return TimedOut(op, timeoutMs, started: false); } bool admitted = false; try { @@ -239,6 +266,7 @@ public async Task HandleAsync(JsonObject request, lock (_state) { if (_line.Count > 0) response["waitingAgents"] = _line.Count; } return response; } + catch (OperationCanceledException) when (OutOfTime()) { return TimedOut(op, timeoutMs, admitted); } finally { try { if (admitted) lock (_state) { _active = false; Expire(); } } diff --git a/src/Anode/Core/Bridge/Pipes.cs b/src/Anode/Core/Bridge/Pipes.cs index f40e7e7..6575f68 100644 --- a/src/Anode/Core/Bridge/Pipes.cs +++ b/src/Anode/Core/Bridge/Pipes.cs @@ -296,8 +296,7 @@ public async Task RequestAsync(string op, JsonObject? args = null, i { long left = timeoutMs - (Environment.TickCount64 - started); // With almost no time left, any reply would come too late, and a late reply costs the connection. - if (deadline.IsCancellationRequested || left < Math.Min(100, timeoutMs / 8)) - return JsonLine.Fail($"'{op}' timed out after {timeoutMs} ms while it waited; nothing was sent"); + if (deadline.IsCancellationRequested || left < Math.Min(100, timeoutMs / 8)) return NotSent(op, timeoutMs); request["timeoutMs"] = TimeLeft(timeoutMs, timeoutMs - left); } sent = true; @@ -315,7 +314,7 @@ public async Task RequestAsync(string op, JsonObject? args = null, i // the command: it may already have changed something in the seat. if (sent) Close(); cancel.ThrowIfCancellationRequested(); - return JsonLine.Fail($"'{op}' timed out after {timeoutMs} ms"); + return sent ? JsonLine.Fail($"'{op}' timed out after {timeoutMs} ms") : NotSent(op, timeoutMs); } catch (IOException ex) { @@ -333,6 +332,18 @@ public async Task RequestAsync(string op, JsonObject? args = null, i } } + /// + /// A request whose time ran out before it went out. It carries the seat host's timed_out failure for an + /// action that never got the desktop, so a caller can tell that nothing ran. + /// + private static JsonObject NotSent(string op, int timeoutMs) + { + var failure = JsonLine.Fail($"'{op}' timed out after {timeoutMs} ms while it waited; nothing was sent"); + failure["errorCode"] = "timed_out"; + failure["started"] = false; + return failure; + } + /// /// What is left of a request's time after a wait. Waits under 100 ms (a sixteenth of a shorter time) are the /// ordinary cost of passing a request on and aren't counted, so limits derived from the time, such as how much diff --git a/src/Anode/Mcp/Tools.cs b/src/Anode/Mcp/Tools.cs index 2098805..24602a7 100644 --- a/src/Anode/Mcp/Tools.cs +++ b/src/Anode/Mcp/Tools.cs @@ -446,6 +446,9 @@ public static JsonArray Definitions() /// internal static bool ActsOnScreen(string op) => op.StartsWith("input.", StringComparison.Ordinal) || op is "gamepad.set" or "gamepad.tap"; + /// Whether an operation only reads, as its tool's read-only hint says: stopping it partway changed nothing. + internal static bool ReadsOnly(string op) => All.Any(tool => tool.Op == op && tool.Effect == Effect.ReadOnly); + public static bool TryResolve(string name, out string op, out bool startsDaemon) { foreach (var tool in All)