diff --git a/internal/ai/harness/guard_test.go b/internal/ai/harness/guard_test.go index e9b96bc..ea86be9 100644 --- a/internal/ai/harness/guard_test.go +++ b/internal/ai/harness/guard_test.go @@ -18,6 +18,17 @@ type timeoutSkill struct { func (s timeoutSkill) Timeout() time.Duration { return s.timeout } +// slowSkill is timeoutSkill whose PostProcess succeeds only after its +// timeout has passed. +type slowSkill struct { + timeoutSkill +} + +func (s slowSkill) PostProcess(out echoOutput) (echoOutput, error) { + time.Sleep(3 * s.timeout) + return s.timeoutSkill.PostProcess(out) +} + // blocked is one scripted Generate call that blocks until released. type blocked struct { started chan struct{} @@ -266,6 +277,24 @@ func TestRunTimeout(t *testing.T) { t.Fatalf("rows = %+v, want one provider_error row naming the timeout", rows) } }) + t.Run("work that succeeds late", func(t *testing.T) { + var f llm.Fake + cfg := testConfig(t, &f) + f.QueueGenerate(reply(`{"echo":"taco"}`)) + s := slowSkill{timeoutSkill{timeout: 20 * time.Millisecond}} + out, err := Run(context.Background(), cfg, s, "week-1", echoInput{Word: "taco"}) + if !errors.Is(err, llm.ErrTimeout) { + t.Fatalf("err = %v, want ErrTimeout", err) + } + if out != (echoOutput{}) { + t.Fatalf("out = %+v, want no output", out) + } + assertCalls(t, &f, 1) + rows := runRows(t, cfg.Store) + if len(rows) != 1 || rows[0].Status != string(StatusProviderError) || !strings.Contains(rows[0].Error.String, llm.ErrTimeout.Error()) { + t.Fatalf("rows = %+v, want one provider_error row naming the timeout", rows) + } + }) t.Run("waiting for a slot", 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 5c3bbe6..df0ef1d 100644 --- a/internal/ai/harness/harness.go +++ b/internal/ai/harness/harness.go @@ -165,12 +165,20 @@ func Run[In, Out any](ctx context.Context, cfg Config, s Skill[In, Out], scope s func runOnce[In, Out any](ctx context.Context, cfg Config, s Skill[In, Out], timeout time.Duration, in In) (Out, error) { var zero Out expired := fmt.Errorf("harness: skill %s v%d: %w: no result within %v", s.Name(), s.Version(), llm.ErrTimeout, timeout) - ctx, cancel := context.WithTimeoutCause(ctx, timeout, expired) + deadline := time.Now().Add(timeout) + ctx, cancel := context.WithDeadlineCause(ctx, deadline, expired) defer cancel() log := &runLog{start: store.Now()} out, status, err := execute(ctx, cfg, s, in, log) - if err != nil && context.Cause(ctx) == expired { - err = fmt.Errorf("%w: %w", expired, err) + // 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 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 + } else { + err = fmt.Errorf("%w: %w", expired, err) + } } if saveErr := log.save(ctx, cfg, s.Name(), s.Version(), status, err); saveErr != nil { return zero, errors.Join(err, fmt.Errorf("harness: skill %s v%d: record ai_runs row: %w", s.Name(), s.Version(), saveErr))