[compass] Fix: seat_job can answer finished: true without the end of the command's output

CHANGELOG.md

@@ -2,6 +2,11 @@
 
 ## Unreleased
 
+- **A finished job's reply holds all its output.** `seat_job` and `anode job` could answer `finished: true`
+  with the end of the command's output missing, when the command ended while the reply was being put
+  together: it read the output first and the status second. An agent that stops reading at `finished:
+  true` lost the end of the log, often its summary. The reply now reads the status first, so `finished:
+  true` comes only with the output to its end.
 - **`set_value` checks that the value took.** On a Chrome drop-down list (`<select>`), `seat_element`
   `set_value` reported `performed` while the list kept its old choice, so an agent could submit a
   form with the wrong option. Anode now reads the control back: if it still shows its old value 1.5

docs/DEVELOPMENT-TESTING.md

@@ -41,7 +41,9 @@ input is closed. Use `seat_run` for applications that should outlive the command
 The reply includes `jobId`, `state`, `finished`, `exitCode`, `stdout`, `stderr`, `cursor`,
 `outputTruncated` and `hasMoreOutput`. A running job has no exit code. `completed` means the
 process exited, including a nonzero exit; inspect `exitCode`. `timed_out`, `cancelled` and `failed`
-are distinct states. Wait for `finished: true` to confirm cleanup has ended.
+are distinct states. Wait for `finished: true` to confirm cleanup has ended. A reply that says
+`finished: true` holds the output to its end; when `hasMoreOutput` is also true, `maxChars` cut the page,
+and the rest follows from its `cursor`.
 
 ```json
 {"jobId":"j_RETURNED_ID","after":"RETURNED_CURSOR","waitMs":1000,"maxChars":12000}

src/Anode/Cli/DevelopmentChecks.cs

@@ -141,22 +141,6 @@ public static async Task<string> Jobs()
             Require(page.Str("stdout") == prefix + "\U0001F680" && buffered.Read(page.Str("cursor"), 4).Str("stdout") == "tail",
                 "stream buffer split a Unicode character across output chunks");
         }
-        ProcessStartInfo Worker(string code)
-        {
-            var info = new ProcessStartInfo("powershell.exe");
-            foreach (string arg in new[] { "-NoProfile", "-NonInteractive", "-EncodedCommand",
-                Convert.ToBase64String(Encoding.Unicode.GetBytes("$null = [Console]::In.ReadLine(); " + code)) }) info.ArgumentList.Add(arg);
-            return info;
-        }
-        // Windows PowerShell can take longer than one wait (10 s at most) to start on a cold machine, so read a job
-        // that should finish until it does, for up to 30 s, before judging its result.
-        static async Task<JsonObject> ReadUntilFinished(ExecutionJobs jobs, JsonObject reply)
-        {
-            for (var clock = Stopwatch.StartNew(); reply.Bool("finished") != true && clock.ElapsedMilliseconds < 30000; )
-                reply = await jobs.ReadAsync(new JsonObject { ["jobId"] = reply.Str("jobId"),
-                    ["waitMs"] = (int)Math.Clamp(30000 - clock.ElapsedMilliseconds, 1, 10000) }, reply.Str("agentId")!);
-            return reply;
-        }
         using (var jobs = new ExecutionJobs(() => Worker("[Console]::Out.Write('hello'); [Console]::Error.Write('problem'); exit 7")))
         {
             var done = await ReadUntilFinished(jobs, await jobs.StartAsync(new JsonObject { ["path"] = "unused-test-command", ["waitMs"] = 10000 }, "test-agent"));
@@ -253,6 +237,47 @@ static async Task<JsonObject> ReadUntilFinished(ExecutionJobs jobs, JsonObject r
         }
         return "UTF-8 streams/exit codes, recovery, hard timeouts, cancelled requests, owner-only discovery/read/cancel and cleanup of owned descendants";
     }
+    private static ProcessStartInfo Worker(string code)
+    {
+        var info = new ProcessStartInfo("powershell.exe");
+        foreach (string arg in new[] { "-NoProfile", "-NonInteractive", "-EncodedCommand",
+            Convert.ToBase64String(Encoding.Unicode.GetBytes("$null = [Console]::In.ReadLine(); " + code)) }) info.ArgumentList.Add(arg);
+        return info;
+    }
+    // Windows PowerShell can take longer than one wait (10 s at most) to start on a cold machine, so read a job
+    // that should finish until it does, for up to 30 s, before judging its result.
+    private static async Task<JsonObject> ReadUntilFinished(ExecutionJobs jobs, JsonObject reply)
+    {
+        for (var clock = Stopwatch.StartNew(); reply.Bool("finished") != true && clock.ElapsedMilliseconds < 30000; )
+            reply = await jobs.ReadAsync(new JsonObject { ["jobId"] = reply.Str("jobId"),
+                ["waitMs"] = (int)Math.Clamp(30000 - clock.ElapsedMilliseconds, 1, 10000) }, reply.Str("agentId")!);
+        return reply;
+    }
+    /// <summary>
+    /// A read that says a job finished holds its output to the end, even when the job finishes while the read is
+    /// between the job's status and its output; an agent stops reading at <c>finished: true</c>.
+    /// </summary>
+    public static async Task<string> JobTail()
+    {
+        using var jobs = new ExecutionJobs(() => Worker("[Console]::Out.Write('head'); [Threading.Thread]::Sleep(200); [Console]::Out.Write('tail')"));
+        var started = await jobs.StartAsync(new JsonObject { ["path"] = "unused-test-command", ["waitMs"] = 0 }, "test-agent");
+        bool between = false;
+        jobs.BetweenStatusAndOutput = async () =>
+        {
+            jobs.BetweenStatusAndOutput = null;
+            between = true;
+            var done = await ReadUntilFinished(jobs, started);
+            Require(done.Bool("finished") == true, "the job did not finish: " + done.Str("summary"));
+        };
+        var reply = await jobs.ReadAsync(new JsonObject { ["jobId"] = started.Str("jobId") }, "test-agent");
+        var rest = await jobs.ReadAsync(new JsonObject { ["jobId"] = started.Str("jobId"), ["after"] = reply.Str("cursor") }, "test-agent");
+        Require(between, "the read never paused between the job's status and its output");
+        Require(reply.Str("stdout") + rest.Str("stdout") == "headtail" && rest.Bool("finished") == true,
+            $"output was lost: '{reply.Str("stdout")}' then '{rest.Str("stdout")}'");
+        Require(reply.Bool("finished") != true || (reply.Bool("hasMoreOutput") == false && rest.Str("stdout") == "" && rest.Str("stderr") == ""),
+            $"a reply said finished: true without the end of the output: it had '{reply.Str("stdout")}', and '{rest.Str("stdout")}' followed");
+        return "a job that finishes during a read is reported finished only with its output to the end";
+    }
     public static async Task<string> CancelledStart()
     {
         int starts = 0;

src/Anode/Cli/SelfTest.cs

@@ -135,6 +135,7 @@ public static int Run(string[] args)
         Check(results, "desktop repeated elements", DesktopChecks.RepeatedElements);
         Check(results, "execution output", DevelopmentChecks.Output);
         Check(results, "execution jobs", () => DevelopmentChecks.Jobs().GetAwaiter().GetResult());
+        Check(results, "execution job tail", () => DevelopmentChecks.JobTail().GetAwaiter().GetResult());
         Check(results, "cancelled execution", () => DevelopmentChecks.CancelledStart().GetAwaiter().GetResult());
         Check(results, "malformed pipe messages", () => TransportChecks.MalformedMessages().GetAwaiter().GetResult());
         Check(results, "agent ownership", () => AgentChecks.Ownership().GetAwaiter().GetResult());

src/Anode/Core/Processes/ExecutionJobs.cs

@@ -39,6 +39,8 @@ public void Stop(string reason)
     private readonly Dictionary<string, Job> _jobs = new();
     private readonly Func<ProcessStartInfo> _workerInfo;
     private bool _disposed;
+    /// <summary>For the quick checks: runs while a read is between a job's status and its output.</summary>
+    internal Func<Task>? BetweenStatusAndOutput { get; set; }
     public ExecutionJobs(Func<ProcessStartInfo>? workerInfo = null) => _workerInfo = workerInfo ?? (() => new ProcessStartInfo(Env.ExecutablePath, "__exec-worker"));
 
     public async Task<JsonObject> StartAsync(JsonObject request, string agentId, CancellationToken cancel = default)
@@ -163,19 +165,24 @@ public async Task<JsonObject> ReadAsync(JsonObject request, string agentId, Canc
         int wait = request.Int("waitMs") ?? 0;
         if (!job.Done.Task.IsCompleted && wait > 0)
             await Task.WhenAny(job.Done.Task, Task.Delay(wait, cancel)).WaitAsync(cancel).ConfigureAwait(false);
-        JsonObject result = job.Output.Read(request.Str("after"), request.Int("maxChars") ?? 12000);
+        // The status comes before the output: a job finishes only after its output is drained, so a page read
+        // after a finished status holds everything to the end. Read the other way round, a job that finished in
+        // between was reported finished with its last output missing.
+        (string State, bool Finished, int WorkerPid, int Session, int? ExitCode, string? Error, long ElapsedMs) status;
         lock (job.Gate)
-        {
-            result["jobId"] = job.Id;
-            result["agentId"] = job.AgentId;
-            result["state"] = job.State;
-            result["finished"] = job.Done.Task.IsCompleted;
-            result["workerPid"] = job.WorkerPid;
-            result["session"] = job.Session;
-            result["exitCode"] = job.ExitCode;
-            result["error"] = job.Error;
-            result["elapsedMs"] = (long)((job.Finished ?? DateTime.UtcNow) - job.Started).TotalMilliseconds;
-        }
+            status = (job.State, job.Done.Task.IsCompleted, job.WorkerPid, job.Session, job.ExitCode, job.Error,
+                (long)((job.Finished ?? DateTime.UtcNow) - job.Started).TotalMilliseconds);
+        if (BetweenStatusAndOutput is { } gap) await gap().ConfigureAwait(false);
+        JsonObject result = job.Output.Read(request.Str("after"), request.Int("maxChars") ?? 12000);
+        result["jobId"] = job.Id;
+        result["agentId"] = job.AgentId;
+        result["state"] = status.State;
+        result["finished"] = status.Finished;
+        result["workerPid"] = status.WorkerPid;
+        result["session"] = status.Session;
+        result["exitCode"] = status.ExitCode;
+        result["error"] = status.Error;
+        result["elapsedMs"] = status.ElapsedMs;
         static string Printable(string text) => string.Concat(text.Select(c => char.IsControl(c) && c is not '\n' and not '\r' and not '\t' ? ' ' : c));
         result["summary"] = $"{job.Id}: {result.Str("state")}, exit code {result["exitCode"]?.ToString() ?? "pending"}. Cursor {result.Str("cursor")}."
             + (result.Bool("outputTruncated") == true ? " Earlier output was discarded; save complete logs from the command when needed." : "")