review: classify inspector timeout from the wait error, not a late ctx re-sample

cefc02f→main·

dipree·1mo ago·3 files·+65 added/-14 removed

Reading agentCtx.Err() after Wait() returns has a tiny window: if an inspector completes naturally just before its deadline, the deadline can fire in the gap before the read and the agent context reports DeadlineExceeded, falsely flagging a timeout.

Classify from waitErr instead, which the Process contract sets to the context cause only when the process was actually killed by it (templateProcess returns ctx.Err() only when cmd.Wait errored). A natural completion returns nil regardless of a deadline firing a moment later, so errors.Is(waitErr, context.DeadlineExceeded) is the atomic, race-free signal in both Run and RunMulti. Drops the now-unused agent-ctx param from the RunMulti goroutine.

Adds TestRun_NaturalCompletionPastDeadlineIsNotTimeout (process finishes cleanly after the deadline elapses -> Succeeded, not a timeout); 'go test -race' on the package is clean.

Sessions

eaf38faaf53dView transcript

Changes

3

• cmd/entire/cli/review

• Mrun.go+7/-6

• Mrun_multi.go+10/-8

• Mrun_test.go+48

135 unmodified lines

136
137
138
139
140
141
142
143
144
139
140
141
142
143
144
145
146
147
148

135 unmodified lines

waitErr := proc.Wait()
    finished := time.Now()
    // agentCtx.Err() is immutable once set, so DeadlineExceeded means this
    // inspector's own deadline fired first; a parent cancellation (user Ctrl+C)
    // propagates as Canceled instead. Reading only agentCtx is therefore
    // race-free — no need to also sample the parent ctx, which could change
    // between the two reads and misclassify a real timeout.
    timedOut := agentCtx.Err() == context.DeadlineExceeded
    // Classify from waitErr, the termination cause captured when Wait returned:
    // the Process contract returns DeadlineExceeded when the process was killed
    // by this inspector's deadline and Canceled on a parent cancellation (user
    // Ctrl+C). Using waitErr instead of re-sampling agentCtx avoids a deadline
    // firing in the gap after a natural completion (waitErr == nil) and producing
    // a false timeout.
    timedOut := errors.Is(waitErr, context.DeadlineExceeded)
    if shouldEmitSyntheticRunError(ctx, waitErr) {
        synthEvent := reviewtypes.RunError{Err: waitErr}
        buffer = append(buffer, synthEvent)

Mcmd/entire/cli/review/run.go+7/-6

24 unmodified lines

25
26
27
28
29
30
31
115 unmodified lines

147
148
149
149
150
151
152
153
8 unmodified lines

162
163
164
164
165
166
167
168
165
166
167
168
169
170
171
170
172
173
174
175
6 unmodified lines

182
183
184
183
185
186
187
188

24 unmodified lines

import (
    "context"
    "errors"
    "log/slog"
    "sync"
    "time"
115 unmodified lines

}
    states[i].proc = proc
    wg.Add(1)
    go func(idx int, p reviewtypes.Process, ac context.Context, cancel context.CancelFunc) {
    go func(idx int, p reviewtypes.Process, cancel context.CancelFunc) {
        defer wg.Done()
        defer cancel()
        for ev := range p.Events() {
8 unmodified lines

// happens-before, so it covers these writes regardless of the fanIn
        // sends below.
        //
        // ac.Err() is immutable once set, so DeadlineExceeded means THIS
        // agent's deadline fired first; a parent cancellation (user Ctrl+C)
        // propagates as Canceled instead. Reading only ac is race-free — also
        // sampling the parent ctx could change between the two reads and
        // misclassify a real timeout as a cancellation.
        // Classify from waitErr (the cause captured when Wait returned): the
        // Process contract returns DeadlineExceeded when killed by THIS agent's
        // deadline and Canceled on a parent cancellation. Using waitErr instead
        // of re-sampling the agent context avoids a deadline firing in the gap
        // after a natural completion (waitErr == nil) and producing a false
        // timeout.
        states[idx].waitErr = waitErr
        states[idx].timedOut = ac.Err() == context.DeadlineExceeded
        states[idx].timedOut = errors.Is(waitErr, context.DeadlineExceeded)
        states[idx].finishedAt = finishedAt
        if shouldEmitSyntheticRunError(ctx, waitErr) {
            fanIn <- taggedEvent{agentIdx: idx, ev: reviewtypes.RunError{Err: waitErr}} 
6 unmodified lines

Duration:  finishedAt.Sub(states[idx].startedAt),
            Err:       waitErr,
        })
    }
    }(i, proc, agentCtx, cancelAgent)
    }(i, proc, cancelAgent)
}

// Close fanIn after all forwarding goroutines finish. This goroutine

Mcmd/entire/cli/review/run_multi.go+10/-8

623 unmodified lines

624
625
626
627
628
629
630
631
632
633
634
635
636
637
638
639
640
641
642
643
644
645
646
647
648
649
650
651
652
653
654
655
656
657
658
659
660
661
662
663
664
665
666
667
668
669
670
671
672
673
674

623 unmodified lines

t.Errorf("err = %v, must not be a timeout for a parent cancel", run.Err)
    }
}

// lateNaturalReviewer's process ignores its context and completes naturally
// (Wait returns nil) only after a delay — modeling an inspector that finishes
// just as (or after) its deadline elapses. It exercises that timeout
// classification keys off the wait error, not a late re-sample of the agent
// context (which would already read DeadlineExceeded and falsely flag it).
type lateNaturalReviewer struct {
    name  string
    delay time.Duration
}

func (r *lateNaturalReviewer) Name() string { return r.name }
func (r *lateNaturalReviewer) Start(_ context.Context, _ reviewtypes.RunConfig) (reviewtypes.Process, error) {
    return &lateNaturalProcess{delay: r.delay}, nil
}

type lateNaturalProcess struct{ delay time.Duration }

func (p *lateNaturalProcess) Events() <-chan reviewtypes.Event {
    ch := make(chan reviewtypes.Event)
    close(ch)
    return ch
}
func (p *lateNaturalProcess) Wait() error {
    time.Sleep(p.delay)
    return nil // completed cleanly, regardless of the (already-elapsed) deadline
}

func TestRun_NaturalCompletionPastDeadlineIsNotTimeout(t *testing.T) {
    t.Parallel()
    rec := &stubSinkRecorder{}
    summary, err := Run(
        context.Background(),
        &lateNaturalReviewer{name: "claude-code", delay: 30 * time.Millisecond},
        reviewtypes.RunConfig{InspectorTimeout: 5 * time.Millisecond}, // deadline elapses during Wait
        []reviewtypes.Sink{rec},
    )
    if err != nil && strings.Contains(err.Error(), "timed out") {
        t.Errorf("err = %v, must not be a timeout for a natural completion", err)
    }
    run := summary.AgentRuns[0]
    if run.Status != reviewtypes.AgentStatusSucceeded {
        t.Errorf("status = %v, want Succeeded (clean completion, not a false timeout)", run.Status)
    }
    if run.Err != nil {
        t.Errorf("run.Err = %v, want nil", run.Err)
    }
}