diff --git a/internal/ai/harness/guard_test.go b/internal/ai/harness/guard_test.go index 04eecd7..3b7f654 100644 --- a/internal/ai/harness/guard_test.go +++ b/internal/ai/harness/guard_test.go @@ -29,6 +29,17 @@ func (s slowSkill) PostProcess(out echoOutput) (echoOutput, error) { return s.timeoutSkill.PostProcess(out) } +// slowFailingSkill is timeoutSkill whose PostProcess fails only after its +// timeout has passed. +type slowFailingSkill struct { + timeoutSkill +} + +func (s slowFailingSkill) PostProcess(echoOutput) (echoOutput, error) { + time.Sleep(3 * s.timeout) + return echoOutput{}, errors.New("cannot finish") +} + // blocked is one scripted Generate call that blocks until released. type blocked struct { started chan struct{} @@ -295,6 +306,25 @@ func TestRunTimeout(t *testing.T) { t.Fatalf("rows = %+v, want one provider_error row naming the timeout", rows) } }) + t.Run("work that fails late", func(t *testing.T) { + var f llm.Fake + cfg := testConfig(t, &f) + f.QueueGenerate(reply(`{"echo":"taco"}`)) + s := slowFailingSkill{timeoutSkill{timeout: 20 * time.Millisecond}} + _, err := Run(context.Background(), cfg, s, "week-1", echoInput{Word: "taco"}) + if !errors.Is(err, llm.ErrTimeout) || !strings.Contains(err.Error(), "cannot finish") { + t.Fatalf("err = %v, want ErrTimeout and the post-process failure", err) + } + assertCalls(t, &f, 1) + // The row records the timeout the caller received, not the + // bad_output a post-process failure in time would be, and keeps + // the underlying error. + rows := runRows(t, cfg.Store) + if len(rows) != 1 || rows[0].Status != string(StatusProviderError) || + !strings.Contains(rows[0].Error.String, llm.ErrTimeout.Error()) || !strings.Contains(rows[0].Error.String, "cannot finish") { + t.Fatalf("rows = %+v, want one provider_error row naming the timeout and the post-process failure", rows) + } + }) t.Run("row saved late", func(t *testing.T) { var f llm.Fake cfg := testConfig(t, &f) diff --git a/internal/ai/harness/harness.go b/internal/ai/harness/harness.go index c1d7296..2388247 100644 --- a/internal/ai/harness/harness.go +++ b/internal/ai/harness/harness.go @@ -124,7 +124,8 @@ func (e *BadOutputError) Unwrap() error { return llm.ErrBadOutput } // cfg.Guard's slots while it runs. // // A run that has not ended within s.Timeout() fails with an error matching -// llm.ErrTimeout. When ctx is done first, Run returns ctx.Err(); the run +// llm.ErrTimeout, wrapping the error its work returned if any, and its row +// records StatusProviderError whatever that work's outcome. When ctx is done first, Run returns ctx.Err(); the run // goes on for the callers still waiting for it, and is cancelled when none // is left. // @@ -180,14 +181,16 @@ func runOnce[In, Out any](ctx context.Context, cfg Config, s Skill[In, Out], tim log := &runLog{id: store.NewID(), start: store.Now()} out, status, err := execute(ctx, cfg, s, in, log) // Work that only ends after the deadline, such as a slow PostProcess, - // may return no error; it is still a timeout, not a success. The clock + // is a timeout whatever it returned, so its row says provider_error + // like the caller's error, which keeps any underlying error. The clock // is checked as well as ctx because ctx's timer may not have fired yet. if context.Cause(ctx) == expired || !time.Now().Before(deadline) { if err == nil { - err, status = expired, StatusProviderError + err = expired } else { err = fmt.Errorf("%w: %w", expired, err) } + status = StatusProviderError } // The saves ignore the callers' cancellation, so a cancelled run is // recorded too, but each is bounded. Work that ended in time must also