]> git.giacomolli.uk - onechat/blob - subagent_run_test.go
Shorten the daemon log lines
[onechat] / subagent_run_test.go
1 package main
2
3 import (
4 "context"
5 "io"
6 "net/http"
7 "os"
8 "path/filepath"
9 "strconv"
10 "strings"
11 "sync/atomic"
12 "testing"
13 "time"
14
15 "github.com/stretchr/testify/require"
16 )
17
18 // subagentTestFullContext is the error body of a call whose input does not fit
19 // in the context of the model.
20 const subagentTestFullContext = `{"error": {"message": "Your input exceeds the context window of this model.", "type": "invalid_request_error", "code": "context_length_exceeded"}}`
21
22 func TestSpawnRunsASubagentInTheBackground(t *testing.T) {
23 server := newModelFake(t)
24 var test *TurnTestLoop
25 server.reply = func(w http.ResponseWriter, call ModelFakeCall) {
26 last := subagentTestLastItem(call)
27 switch {
28 case subagentTestCall(call) && last["type"] == "function_call_output":
29 // The report comes after the reply of the turn of the spawn.
30 test.events.WaitFor(t, "reply", 1)
31 modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem("There are 3 files.")}, 100, 0, 5))
32 case subagentTestCall(call):
33 modelWriteEvents(w, modelCompletedEvent([]any{modelFunctionCallItem("fc_1", "call_1", "shell", `{"command":"pwd"}`)}, 100, 0, 5))
34 case last["type"] == "function_call_output":
35 modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem("Started.")}, 100, 0, 5))
36 case strings.HasPrefix(subagentTestText(last), "["):
37 modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem("Noted.")}, 100, 0, 5))
38 default:
39 modelWriteEvents(w, modelCompletedEvent([]any{modelFunctionCallItem("fc_1", "call_1", "spawn", `{"tasks":["Count the files."],"effort":null}`)}, 100, 0, 5))
40 }
41 }
42
43 test = newTestTurnLoop(t, server)
44 _, err := test.loop.Submit(terminalSource, "Count the files in a subagent.")
45 require.NoError(t, err)
46 test.events.WaitFor(t, "idle", 2)
47
48 name := test.events.Last("subagent")
49 require.True(t, subagentNameValid(name), name)
50 work := filepath.Join(test.loop.runs.subagents.dir, name, "work")
51 require.DirExists(t, work)
52
53 report := "[" + name + "]\nThere are 3 files.\n\nFull chat: zoom(\"" + name + "\")"
54 require.Equal(t, []string{
55 "user: Count the files in a subagent.",
56 `tool: spawn {"tasks":["Count the files."],"effort":null}`,
57 "echo: Started " + name + ". Each one's report will reach you as a message when it finishes.",
58 "reply: Started.",
59 "work: " + report,
60 "reply: Noted.",
61 }, test.Log(t))
62 require.Equal(t, Event{
63 Kind: "work",
64 ID: 4,
65 Text: report,
66 Source: name,
67 Status: subagentFinished,
68 }, test.events.LastEvent("work"))
69 require.Equal(t, "subagent "+name+" done\n", test.logs.String())
70
71 var first, second *ModelFakeCall
72 for n := range server.Calls() {
73 call := server.Call(n)
74 if !subagentTestCall(call) {
75 continue
76 }
77
78 if first == nil {
79 first = &call
80 } else {
81 second = &call
82 }
83 }
84
85 require.NotNil(t, second)
86
87 // The first request of the subagent holds the view, the state, and its
88 // whole log, with its own prompt and tools.
89 texts := turnInputTexts(t, *first)
90 view := strings.Join(texts[:len(texts)-2], "")
91 require.True(t, strings.HasPrefix(view, "<chat>\n0+1|user: Count the files in a subagent.\n1+1|tool: spawn"), view)
92 require.Equal(t, "</chat>\n\nNow: Thursday 2026-01-01 12:00 +00:00", texts[len(texts)-2])
93 require.Equal(t, "0|note: subagent\n\n1|user: Count the files.", texts[len(texts)-1])
94
95 instructions, err := test.agent.SubagentPrompt()
96 require.NoError(t, err)
97 require.Equal(t, instructions, first.body["instructions"])
98
99 var tools []string
100 for _, tool := range first.body["tools"].([]any) {
101 tools = append(tools, tool.(map[string]any)["name"].(string))
102 }
103
104 require.Equal(t, []string{"zoom", "date", "shell", "read", "write", "edit"}, tools)
105 require.Equal(t, work+"\n", subagentTestLastItem(*second)["output"])
106
107 subagent, err := test.loop.runs.subagents.Get(t.Context(), name)
108 require.NoError(t, err)
109
110 log, err := subagent.Show()
111 require.NoError(t, err)
112 require.Equal(t, "0|note: subagent\n\n1|user: Count the files.\n\n2|tool: shell {\"command\":\"pwd\"}\n\n3|echo: "+work+"\n\n\n4|reply: There are 3 files.", log)
113
114 var agents []string
115 for _, record := range modelReadUsage(t, test.usagePath) {
116 agents = append(agents, record.Agent)
117 }
118
119 require.ElementsMatch(t, []string{"", "", "", name, name}, agents)
120 }
121
122 func TestReportJoinsTheNextRequestOfARunningTurn(t *testing.T) {
123 server := newModelFake(t)
124 arrived := make(chan struct{})
125 release := make(chan struct{})
126 server.reply = func(w http.ResponseWriter, call ModelFakeCall) {
127 if call.number == 0 {
128 close(arrived)
129 <-release
130 modelWriteEvents(w, modelCompletedEvent([]any{modelFunctionCallItem("fc_1", "call_1", "date", `{"id":0}`)}, 100, 0, 5))
131
132 return
133 }
134
135 modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem("done")}, 100, 0, 5))
136 }
137
138 test := newTestTurnLoop(t, server)
139 _, err := test.loop.Submit(terminalSource, "first")
140 require.NoError(t, err)
141
142 <-arrived
143 report := subagentReport("GreenOtter", []string{"It is done."})
144 test.loop.Report("GreenOtter", report, subagentFinished)
145 close(release)
146
147 test.events.WaitFor(t, "idle", 1)
148 require.Equal(t, report, subagentTestText(subagentTestLastItem(server.Call(1))))
149
150 time.Sleep(50 * time.Millisecond)
151 require.Equal(t, 2, server.Calls())
152 require.Equal(t, 1, test.events.Count("busy"))
153 }
154
155 func TestReportOfAStoppedSubagentStartsNoTurn(t *testing.T) {
156 server := newModelFake(t)
157 test := newTestTurnLoop(t, server)
158 report := subagentReport("GreenOtter", []string{"failed: context canceled"})
159 test.loop.Report("GreenOtter", report, subagentStopped)
160
161 test.events.WaitFor(t, "work", 1)
162 time.Sleep(50 * time.Millisecond)
163 require.Equal(t, []string{"work: " + report}, test.Log(t))
164 require.Zero(t, server.Calls())
165 require.Zero(t, test.events.Count("busy"))
166 }
167
168 func TestFullContextGivesAFailedReport(t *testing.T) {
169 server := newModelFake(t)
170 server.reply = func(w http.ResponseWriter, call ModelFakeCall) {
171 if subagentTestCall(call) {
172 w.WriteHeader(http.StatusBadRequest)
173 _, _ = io.WriteString(w, subagentTestFullContext)
174
175 return
176 }
177
178 modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem("It failed.")}, 100, 0, 5))
179 }
180
181 test := newTestTurnLoop(t, server)
182 _, err := test.loop.runs.Spawn(t.Context(), []string{"Read the big file."}, nil)
183 require.NoError(t, err)
184 test.events.WaitFor(t, "idle", 1)
185
186 name := test.events.Last("subagent")
187 require.Equal(t, []string{
188 "work: [" + name + "]\nfailed: model call: HTTP 400: " + subagentTestFullContext + "\n\nFull chat: zoom(\"" + name + "\")",
189 "reply: It failed.",
190 }, test.Log(t))
191 require.Equal(t, subagentFailed, test.events.LastEvent("work").Status)
192 require.Equal(t, "subagent "+name+" failed: model call: HTTP 400: "+subagentTestFullContext+"\n", test.logs.String())
193 }
194
195 func TestSubagentHasItsOwnEffortAndNoSpawn(t *testing.T) {
196 server := newModelFake(t)
197 server.reply = func(w http.ResponseWriter, call ModelFakeCall) {
198 if subagentTestCall(call) && subagentTestLastItem(call)["type"] != "function_call_output" {
199 modelWriteEvents(w, modelCompletedEvent([]any{modelFunctionCallItem("fc_1", "call_1", "spawn", `{"tasks":["More."],"effort":null}`)}, 100, 0, 5))
200
201 return
202 }
203
204 modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem("ok")}, 100, 0, 5))
205 }
206
207 test := newTestTurnLoop(t, server)
208 runs := test.loop.runs
209 _, err := runs.Spawn(t.Context(), nil, nil)
210 require.EqualError(t, err, "no tasks")
211
212 effort := "max"
213 _, err = runs.Spawn(t.Context(), []string{"Think."}, &effort)
214 require.EqualError(t, err, `no effort "max": one of low, medium, high, xhigh`)
215
216 effort = "high"
217 _, err = runs.Spawn(t.Context(), []string{"Think hard."}, &effort)
218 require.NoError(t, err)
219 test.events.WaitFor(t, "idle", 1)
220
221 for n := range server.Calls() {
222 call := server.Call(n)
223 if subagentTestCall(call) {
224 require.Equal(t, "high", call.body["reasoning"].(map[string]any)["effort"])
225 }
226 }
227
228 subagent, err := runs.subagents.Get(t.Context(), test.events.Last("subagent"))
229 require.NoError(t, err)
230
231 log, err := subagent.Show()
232 require.NoError(t, err)
233 require.Equal(t, "0|note: subagent at effort high\n\n1|user: Think hard.\n\n2|tool: spawn {\"tasks\":[\"More.\"],\"effort\":null}\n\n3|echo: error: unknown tool \"spawn\"\n\n4|reply: ok", log)
234
235 entries, err := os.ReadDir(runs.subagents.dir)
236 require.NoError(t, err)
237 require.Len(t, entries, 1)
238 }
239
240 func TestTellReachesARunningSubagentBetweenItsToolCalls(t *testing.T) {
241 server := newModelFake(t)
242 arrived := make(chan struct{})
243 told := make(chan struct{})
244 server.reply = func(w http.ResponseWriter, call ModelFakeCall) {
245 switch {
246 case !subagentTestCall(call):
247 modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem("Noted.")}, 100, 0, 5))
248 case call.number == 0:
249 close(arrived)
250 <-told
251 modelWriteEvents(w, modelCompletedEvent([]any{modelFunctionCallItem("fc_1", "call_1", "shell", `{"command":"true"}`)}, 100, 0, 5))
252 default:
253 modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem("Used the second disk.")}, 100, 0, 5))
254 }
255 }
256
257 test := newTestTurnLoop(t, server)
258 runs := test.loop.runs
259 _, err := runs.Spawn(t.Context(), []string{"Copy the files."}, nil)
260 require.NoError(t, err)
261
262 <-arrived
263 name := test.events.Last("subagent")
264 output, err := runs.Tell(t.Context(), name, "Use the second disk.")
265 require.NoError(t, err)
266 require.Equal(t, "Sent. "+name+" reads it between its tool calls, and its report answers it.", output)
267 close(told)
268
269 test.events.WaitFor(t, "idle", 1)
270 require.Equal(t, "Use the second disk.", subagentTestText(subagentTestLastItem(server.Call(1))))
271 require.Equal(t, "work: "+subagentReport(name, []string{"Used the second disk."}), test.Log(t)[0])
272 }
273
274 func TestTellAfterTheFinalAnswerStartsAnotherChain(t *testing.T) {
275 server := newModelFake(t)
276 arrived := make(chan struct{})
277 told := make(chan struct{})
278 server.reply = func(w http.ResponseWriter, call ModelFakeCall) {
279 switch {
280 case !subagentTestCall(call):
281 modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem("Noted.")}, 100, 0, 5))
282 case call.number == 0:
283 close(arrived)
284 <-told
285 modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem("First.")}, 100, 0, 5))
286 default:
287 modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem("Second.")}, 100, 0, 5))
288 }
289 }
290
291 test := newTestTurnLoop(t, server)
292 runs := test.loop.runs
293 _, err := runs.Spawn(t.Context(), []string{"Count."}, nil)
294 require.NoError(t, err)
295
296 <-arrived
297 name := test.events.Last("subagent")
298 _, err = runs.Tell(t.Context(), name, "Count again.")
299 require.NoError(t, err)
300 close(told)
301
302 test.events.WaitFor(t, "idle", 1)
303 require.Equal(t, "0|note: subagent\n\n1|user: Count.\n\n2|user: Count again.\n\n3|reply: First.", subagentTestText(subagentTestLastItem(server.Call(1))))
304 require.Equal(t, "work: "+subagentReport(name, []string{"First.", "Second."}), test.Log(t)[0])
305 }
306
307 func TestTellToAFinishedSubagentGoesOnFromItsLog(t *testing.T) {
308 server := newModelFake(t)
309 server.reply = func(w http.ResponseWriter, call ModelFakeCall) {
310 text := "Noted."
311 if subagentTestCall(call) {
312 text = "Reply " + strconv.Itoa(call.number) + "."
313 }
314
315 modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem(text)}, 100, 0, 5))
316 }
317
318 test := newTestTurnLoop(t, server)
319 runs := test.loop.runs
320 effort := "high"
321 _, err := runs.Spawn(t.Context(), []string{"Count."}, &effort)
322 require.NoError(t, err)
323 test.events.WaitFor(t, "idle", 1)
324
325 name := test.events.Last("subagent")
326 output, err := runs.Tell(t.Context(), name, "And the hidden files?")
327 require.NoError(t, err)
328 require.Equal(t, "Sent. "+name+"'s reply will reach you as a message.", output)
329 test.events.WaitFor(t, "idle", 2)
330
331 call := server.Call(2)
332 require.True(t, subagentTestCall(call))
333 require.Equal(t, "high", call.body["reasoning"].(map[string]any)["effort"])
334 require.Equal(t, "0|note: subagent at effort high\n\n1|user: Count.\n\n2|reply: Reply 0.\n\n3|user: And the hidden files?", subagentTestText(subagentTestLastItem(call)))
335
336 // The view of the new run holds the chat of now, with the first report.
337 texts := turnInputTexts(t, call)
338 require.Contains(t, strings.Join(texts[:len(texts)-2], ""), "work: ["+name+"]")
339 require.Equal(t, "work: "+subagentReport(name, []string{"Reply 2."}), test.Log(t)[2])
340
341 _, err = runs.Tell(t.Context(), "BlueFox", "Hello.")
342 require.EqualError(t, err, "no agent BlueFox")
343 }
344
345 func TestStopEndsASubagentAndItsCommand(t *testing.T) {
346 server := newModelFake(t)
347 server.reply = func(w http.ResponseWriter, call ModelFakeCall) {
348 modelWriteEvents(w, modelCompletedEvent([]any{modelFunctionCallItem("fc_1", "call_1", "shell", `{"command":"touch started && sleep 30"}`)}, 100, 0, 5))
349 }
350
351 test := newTestTurnLoop(t, server)
352 runs := test.loop.runs
353 _, err := runs.Spawn(t.Context(), []string{"Wait long."}, nil)
354 require.NoError(t, err)
355
356 name := test.events.Last("subagent")
357 subagent, err := runs.subagents.Get(t.Context(), name)
358 require.NoError(t, err)
359
360 require.Eventually(t, func() bool {
361 _, err := os.Stat(filepath.Join(subagent.WorkDir(), "started"))
362 return err == nil
363 }, 10*time.Second, time.Millisecond)
364
365 start := time.Now()
366 found, err := test.loop.StopSubagent(name)
367 require.NoError(t, err)
368 require.True(t, found)
369
370 test.events.WaitFor(t, "work", 1)
371 require.Less(t, time.Since(start), 10*time.Second)
372 require.Equal(t, []string{
373 "note: Stopped by the user: " + name + ".",
374 "work: " + subagentReport(name, []string{"stopped"}),
375 }, test.Log(t))
376 require.Equal(t, subagentStopped, test.events.LastEvent("work").Status)
377 require.Equal(t, "subagent "+name+" stopped\n", test.logs.String())
378
379 log, err := subagent.Show()
380 require.NoError(t, err)
381 require.Contains(t, log, "echo: \n[interrupted]")
382
383 found, err = test.loop.StopSubagent(name)
384 require.NoError(t, err)
385 require.False(t, found)
386
387 time.Sleep(50 * time.Millisecond)
388 require.Zero(t, test.events.Count("busy"))
389 }
390
391 func TestCloseEndsTheSubagentsWithNoReport(t *testing.T) {
392 server := newModelFake(t)
393 arrived := make(chan struct{})
394 release := make(chan struct{})
395 t.Cleanup(func() {
396 close(release)
397 })
398
399 server.reply = func(w http.ResponseWriter, call ModelFakeCall) {
400 close(arrived)
401 <-release
402 }
403
404 test := newTestTurnLoop(t, server)
405 runs := test.loop.runs
406 _, err := runs.Spawn(t.Context(), []string{"Wait."}, nil)
407 require.NoError(t, err)
408
409 <-arrived
410 runs.Close()
411 require.Empty(t, runs.running)
412 require.Empty(t, test.Log(t))
413
414 _, err = runs.Spawn(t.Context(), []string{"Again."}, nil)
415 require.ErrorIs(t, err, errSubagentClosed)
416
417 entries, err := os.ReadDir(runs.subagents.dir)
418 require.NoError(t, err)
419 require.Len(t, entries, 1)
420 }
421
422 func TestRestartResumesTheCutSubagents(t *testing.T) {
423 server := newModelFake(t)
424 arrived := make(chan struct{}, 1)
425 release := make(chan struct{})
426 t.Cleanup(func() {
427 close(release)
428 })
429
430 var restarted atomic.Bool
431 server.reply = func(w http.ResponseWriter, call ModelFakeCall) {
432 switch {
433 case subagentTestCall(call) && !restarted.Load():
434 arrived <- struct{}{}
435 <-release
436 case subagentTestCall(call):
437 modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem("Built.")}, 100, 0, 5))
438 default:
439 modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem("Noted.")}, 100, 0, 5))
440 }
441 }
442
443 agent, err := openAgent(t.TempDir())
444 require.NoError(t, err)
445
446 first := &TurnEventRecorder{}
447 loop, _, stop := subagentTestStart(t, agent, server, first)
448 _, err = loop.runs.Spawn(t.Context(), []string{"Build the project."}, nil)
449 require.NoError(t, err)
450
451 <-arrived
452 name := first.Last("subagent")
453 stop()
454 require.Zero(t, first.Count("work"))
455
456 data, err := os.ReadFile(filepath.Join(agent.dir, subagentWorkFileName))
457 require.NoError(t, err)
458 require.JSONEq(t, `{"running": ["`+name+`"]}`, string(data))
459
460 restarted.Store(true)
461 second := &TurnEventRecorder{}
462 loop, memory, stop := subagentTestStart(t, agent, server, second)
463 defer stop()
464
465 second.WaitFor(t, "idle", 1)
466 note := "The daemon restarted, cutting " + name + "; nothing was lost: go on."
467 log := subagentTestChat(t, memory)
468 require.Equal(t, []string{
469 "note: " + note,
470 "work: " + subagentReport(name, []string{"Built."}),
471 "reply: Noted.",
472 }, log[len(log)-3:])
473
474 subagent, err := loop.runs.subagents.Get(t.Context(), name)
475 require.NoError(t, err)
476
477 text, err := subagent.Show()
478 require.NoError(t, err)
479 require.Equal(t, "0|note: subagent\n\n1|user: Build the project.\n\n2|user: "+note+"\n\n3|reply: Built.", text)
480
481 data, err = os.ReadFile(filepath.Join(agent.dir, subagentWorkFileName))
482 require.NoError(t, err)
483 require.JSONEq(t, `{"running": []}`, string(data))
484 }
485
486 func TestRestartReportsASubagentThatCannotGoOn(t *testing.T) {
487 server := newModelFake(t)
488 agent, err := openAgent(t.TempDir())
489 require.NoError(t, err)
490 require.NoError(t, os.WriteFile(filepath.Join(agent.dir, subagentWorkFileName), []byte(`{"running": ["BlueFox"]}`), 0o600))
491
492 events := &TurnEventRecorder{}
493 _, memory, stop := subagentTestStart(t, agent, server, events)
494 defer stop()
495
496 events.WaitFor(t, "idle", 1)
497 require.Equal(t, []string{
498 "note: The daemon restarted, cutting BlueFox; nothing was lost: go on.",
499 "work: " + subagentReport("BlueFox", []string{"failed: no agent BlueFox"}),
500 "reply: a line",
501 }, subagentTestChat(t, memory))
502 require.Equal(t, subagentFailed, events.LastEvent("work").Status)
503
504 data, err := os.ReadFile(filepath.Join(agent.dir, subagentWorkFileName))
505 require.NoError(t, err)
506 require.JSONEq(t, `{"running": []}`, string(data))
507 }
508
509 // subagentTestStart runs a loop of agent with its memory and subagents in the
510 // agent directory, as the daemon does. The returned function stops the loop
511 // and closes the files.
512 func subagentTestStart(t *testing.T, agent *Agent, server *ModelFake, events *TurnEventRecorder) (*TurnLoop, *Memory, func()) {
513 t.Helper()
514
515 agent.config.Workdir = t.TempDir()
516 clock := newTestClock()
517 memory, err := openMemory(t.Context(), agent.dir, clock.Now, newFakeSummarizer(), discardLog())
518 require.NoError(t, err)
519
520 subagents := newSubagents(filepath.Join(agent.dir, subagentDirName), clock.Now, subagentNameRandom)
521 client := newModelClient(server.URL, ModelAPIKey(modelTestKey), agent.CacheKey(), filepath.Join(agent.dir, "usage.jsonl"))
522 whatsapp, _, _ := whatsappStartTest(t, t.TempDir(), clock)
523 loop, err := newTurnLoop(agent, memory, subagents, whatsapp, newTestSchedules(t, clock.Now), client, clock.Now, discardLog(), events.Add)
524 require.NoError(t, err)
525
526 ctx, cancel := context.WithCancel(t.Context())
527 done := make(chan error)
528 go func() {
529 done <- loop.Run(ctx)
530 }()
531
532 return loop, memory, func() {
533 cancel()
534 require.ErrorIs(t, <-done, context.Canceled)
535 require.NoError(t, subagents.Close())
536 require.NoError(t, memory.Close())
537 }
538 }
539
540 // subagentTestChat returns each message of the chat in memory as
541 // "kind: text".
542 func subagentTestChat(t *testing.T, memory *Memory) []string {
543 t.Helper()
544
545 var lines []string
546 for id := range memory.Len() {
547 message, err := memory.Message(id)
548 require.NoError(t, err)
549
550 lines = append(lines, message.Kind+": "+message.Text)
551 }
552
553 return lines
554 }
555
556 // subagentTestCall tells if call is a call of a subagent.
557 func subagentTestCall(call ModelFakeCall) bool {
558 instructions, _ := call.body["instructions"].(string)
559
560 return strings.HasPrefix(instructions, "You are a subagent")
561 }
562
563 // subagentTestLastItem returns the last input item of call.
564 func subagentTestLastItem(call ModelFakeCall) map[string]any {
565 input := call.body["input"].([]any)
566
567 return input[len(input)-1].(map[string]any)
568 }
569
570 // subagentTestText returns the text of the user message item, or "" for
571 // another item.
572 func subagentTestText(item map[string]any) string {
573 content, _ := item["content"].([]any)
574 var text strings.Builder
575 for _, part := range content {
576 value, _ := part.(map[string]any)["text"].(string)
577 text.WriteString(value)
578 }
579
580 return text.String()
581 }