Files
multica/server/pkg/agent/openclaw_stdout.go
VvV 547fcca069 MUL-5631: fix(openclaw): finish at the result boundary when the CLI does not exit (#6276)
* fix(openclaw): finish at the result boundary when the CLI does not exit

A chat reply was generated and then never delivered. Timeline from a host
running openclaw 2026.5.27, relative to the start of the run:

  T+0s     openclaw started
  T+24s    the complete result blob was written to stdout
  T+8min   process still alive, task slot still held, user saw nothing

processOutput read stdout with io.ReadAll, which returns only at EOF, and EOF
requires every write end of the pipe to be closed. `openclaw agent --local
--json` printed its complete result blob and then did not exit, so the pipe
stayed open, the read never returned, the goroutine never reached cmd.Wait,
and the finished answer sat in the daemon's buffer while the task held its
execution slot until the idle watchdog eventually reclaimed it.

## The boundary already has a precedent here

cursor-agent has the same misbehaviour, and cursor.go already handles it: its
`result` case notes that current versions "can emit the terminal result event
but keep a worker process alive", so it treats result as the protocol
boundary, calls cancel(), and guards its final status switch with
`if resultSeen` so the deliberate kill is not reported as an abort.

openclaw parses one whole-buffer blob rather than line events, so the
equivalent condition is "the buffer parses as a complete result" instead of
"a result line arrived". This change gives openclaw the same three pieces:

  - readOpenclawStdout replaces io.ReadAll. It returns at EOF as before, or
    early once the buffer parses as a complete result AND stdout has been
    idle for 2s, reporting cutShort.
  - On cutShort, Execute cancels the run context so CommandContext kills the
    lingering process and cmd.Wait can return.
  - The status switch gets a leading `case scanResult.cutShort:` so the
    resulting cancellation is not turned into "aborted" — that would discard
    a reply we already hold.

Both read conditions are required. Idle alone is not enough: an agent may
pause for minutes while thinking, and cutting off a partial buffer would
throw away work it has already done, which is worse than the hang. Parseable
alone is not enough either, since more output may still follow. Nothing is
cut short before any output arrives, so a silent agent stays governed purely
by the caller's context and its behaviour is unchanged.

## WaitDelay 10s -> 500ms

Matching cursor-agent, for the same reason. WaitDelay only applies once the
child is gone but its stdio is still held — which is exactly the cut-short
path, since that is where we kill a process still holding the pipe. Leaving
it at 10s would add 10s to every reply that takes this path. A CLI that exits
cleanly never reaches the delay at all. End to end this took the reproduction
from ~12.5s to ~2.9s.

## Verification

  - pkg/agent green with -race under CI's flags (-p 2 -parallel 2); 4
    consecutive runs, no flakes. All existing Openclaw* tests unchanged and
    passing, including TestOpenclawProcessOutputReadError and the
    empty-buffer cases, which exercise the new reader's EOF and error paths.
  - GOOS=windows build, vet and test compilation all pass.
  - 3 new tests, each mutation-verified against the mechanism it guards:
      * io.ReadAll restored -> the test hangs and the dump is the production
        stack: io.ReadAll <- openclawBackend.processOutput.
      * cutShort status guard removed -> status = "aborted" instead of
        "completed", i.e. the reply is thrown away.
      * boundary cancel() removed -> the test hangs in os/exec.(*Cmd).Wait.

* fix(openclaw): keep a delivered result when a descendant outlives WaitDelay

Addresses the review on #6276. The finding is correct and the comment it quoted
was wrong: lowering WaitDelay to 500ms introduced a regression on the
*clean-exit* path, which is worse than the hang this PR set out to fix.

Verified against the documented contract rather than assumed:

  The WaitDelay timer starts when either the associated Context is done or a
  call to Wait observes that the child process has exited, whichever occurs
  first. ... If pipes are closed due to WaitDelay, no Cancel call has occurred,
  and the command has otherwise exited with a successful status, Wait and
  similar methods will return ErrWaitDelay instead of nil.

So a clean exit does reach the delay whenever a descendant still holds one of
the pipes os/exec manages — and this backend has one, since cmd.Stderr is a
plain io.Writer for which os/exec creates an internal pipe plus a copy
goroutine. The path was:

  1. openclaw writes its complete result, closes stdout, exits 0.
  2. readOpenclawStdout returns via EOF, so cutShort is false.
  3. A short-lived descendant keeps stderr open for >500ms.
  4. cmd.Wait returns exec.ErrWaitDelay.
  5. cutShort is false and runCtx.Err() is nil, so the switch fell through to
     "openclaw exited with error" and a fully parsed, deliverable reply was
     reported as failed.

The review is also right that the cursor-agent comparison did not carry over.
cursor ignores *every* exit error once a terminal result is parsed
(`if resultSeen`), whereas this diff had narrowed that protection to
`case scanResult.cutShort:` — which is self-consistent only if the clean-exit
route can never produce an exit error, and it can.

Fix, taking the reviewer's preferred option since it is the smallest and leaves
the WaitDelay timing and the watch goroutine alone: keep the success status when
the error is specifically ErrWaitDelay and a complete result was parsed. By
definition ErrWaitDelay means the process exited successfully, so this cannot
mask a real failure; the only thing lost is a tail of stderr log lines, and that
is logged as a warning. It is deliberately a separate case from cutShort, since
that path cancels on purpose and a Cancel call makes Wait report the kill rather
than ErrWaitDelay.

The comment that stated the wrong premise is rewritten to say what WaitDelay
actually bounds, and why lowering it is still right: the delay is only reached
when something is holding a pipe open, and on the cut-short path we deliberately
kill a process doing exactly that.

Also takes the non-blocking nit: readOpenclawStdout's ticker branch copied the
whole accumulated buffer before checking whether stdout had actually gone idle,
so a large result was reallocated on every 100ms tick. The cheap conditions are
now checked under the lock first and the buffer is copied only once the silence
threshold is met.

Regression test as requested: the parent writes a complete result, closes stdout
and exits 0 while a descendant holds stderr for ~1s (its own stdout goes to
/dev/null so the stdout pipe still reaches EOF), and the final status must be
completed. Mutation-verified — dropping the new case reproduces the reported
failure verbatim:

  status = "failed" (error: "openclaw exited with error: exec: WaitDelay
  expired before I/O complete"), want completed

pkg/agent passes with -race under CI's flags, all pre-existing Openclaw* tests
included, and GOOS=windows build and vet are clean.

---------

Co-authored-by: weiweiwei <weiweiwei@xiaomi.com>
2026-08-03 19:01:12 +08:00

142 lines
4.6 KiB
Go

package agent
import (
"io"
"sync"
"time"
)
// openclawResultIdleGrace is how long stdout must stay silent *after* the
// buffer already parses as a complete openclaw result before readOpenclawStdout
// treats the run as finished.
//
// Deliberately generous. The cheap check — does the buffer parse as a complete
// result? — is the real gate; this only guards against declaring victory
// mid-write if a future openclaw flushes a result and then appends more. 2s is
// far longer than the gap inside one flush, and it costs nothing in the normal
// case because a CLI that exits reaches EOF and never consults it.
const openclawResultIdleGrace = 2 * time.Second
// openclawStdoutPoll is how often the reader re-evaluates its exit conditions.
const openclawStdoutPoll = 100 * time.Millisecond
// readOpenclawStdout drains r and returns the bytes read. It stops at EOF, or
// early once the buffer parses as a complete openclaw result AND stdout has
// been idle for idleGrace — reporting cutShort=true in that second case so the
// caller can cancel the run before waiting on the process.
//
// # Why not io.ReadAll
//
// io.ReadAll returns only at EOF, and EOF requires every write end of the pipe
// to be closed. Observed in production: `openclaw agent --local --json` printed
// its complete result blob — the agent's reply was fully generated — and then
// did not exit. The pipe stayed open, so the read never returned, the goroutine
// never reached cmd.Wait, and the finished reply sat in the daemon's buffer
// while the task held its execution slot:
//
// T+0s openclaw started
// T+24s the complete result blob was written to stdout
// T+8min process still alive, slot still held, user saw nothing
//
// # Why a complete result is the right boundary
//
// This exact hazard is already handled for cursor-agent, whose adapter notes
// that current versions "can emit the terminal result event but keep a worker
// process alive" and therefore treats result as the protocol boundary and
// cancels (see the "result" case in cursor.go). openclaw parses one
// whole-buffer blob rather than line events, so the equivalent condition is
// "the buffer is a complete result" instead of "a result line arrived".
//
// Both conditions are required. Idle alone is not enough — an agent may pause
// for minutes while thinking, and cutting off a partial buffer would discard
// work it has already done, which is worse than the hang. Parseable alone is
// not enough either, since more output may still be coming.
//
// Nothing is cut short before any output appears: idle time is measured from
// the last byte received, so a silent agent remains governed purely by the
// caller's context, exactly as before.
//
// On the cutShort path the internal read goroutine is still blocked in
// r.Read. It exits when the caller's cancellation closes r, which openclaw's
// Execute already arranges. Callers that do not close r on cancellation must
// not use this function.
func readOpenclawStdout(r io.Reader, idleGrace time.Duration) (buf []byte, cutShort bool, err error) {
if idleGrace <= 0 {
idleGrace = openclawResultIdleGrace
}
var (
mu sync.Mutex
acc []byte
lastByte time.Time
readErr error
atEOF bool
)
finished := make(chan struct{})
go func() {
defer close(finished)
chunk := make([]byte, 32*1024)
for {
n, rerr := r.Read(chunk)
if n > 0 {
mu.Lock()
acc = append(acc, chunk[:n]...)
lastByte = time.Now()
mu.Unlock()
}
if rerr != nil {
mu.Lock()
if rerr != io.EOF {
readErr = rerr
}
atEOF = true
mu.Unlock()
return
}
}
}()
ticker := time.NewTicker(openclawStdoutPoll)
defer ticker.Stop()
for {
select {
case <-finished:
// The stream ended on its own: the pre-existing behaviour, with the
// same buffer io.ReadAll would have produced.
mu.Lock()
out, rerr := acc, readErr
mu.Unlock()
return out, false, rerr
case <-ticker.C:
// Check the cheap conditions under the lock first and only copy the
// buffer once the silence threshold is actually met. Copying on every
// tick would allocate the whole accumulated result ~20 times per wait
// window, which for a large result is pure waste.
mu.Lock()
size := len(acc)
last := lastByte
done := atEOF
mu.Unlock()
if done {
continue // let the <-finished branch report the final state
}
if size == 0 || time.Since(last) < idleGrace {
continue
}
mu.Lock()
out := append([]byte(nil), acc...)
mu.Unlock()
if _, ok := parseWholeBufferOpenclawResult(out); !ok {
continue
}
return out, true, nil
}
}
}