X-Git-Url: https://git.giacomolli.uk/onechat/blobdiff_plain/522d7fd117285e4e4ce3ea5ec9b5a1722521b681..98d137c3e945a09f76e85bd18238558c668fdca4:/subagent_run_test.go

diff --git a/subagent_run_test.go b/subagent_run_test.go
index f637dcf..047e6a8 100644
--- a/subagent_run_test.go
+++ b/subagent_run_test.go
@@ -3,6 +3,7 @@ package main
 import (
 	"context"
 	"io"
+	"log/slog"
 	"net/http"
 	"os"
 	"path/filepath"
@@ -28,7 +29,8 @@ func TestSpawnRunsASubagentInTheBackground(t *testing.T) {
 		last := subagentTestLastItem(call)
 		switch {
 		case subagentTestCall(call) && last["type"] == "function_call_output":
-			// The report comes after the reply of the turn of the spawn.
+			// The report comes after the reply of the turn of the
+			// spawn.
 			test.events.WaitFor(t, "reply", 1)
 			modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem("There are 3 files.")}, 100, 0, 5))
 		case subagentTestCall(call):
@@ -62,6 +64,7 @@ func TestSpawnRunsASubagentInTheBackground(t *testing.T) {
 		"work: " + report,
 		"reply: Noted.",
 	}, test.Log(t))
+
 	require.Equal(t, Event{
 		Kind:   "work",
 		ID:     4,
@@ -69,7 +72,8 @@ func TestSpawnRunsASubagentInTheBackground(t *testing.T) {
 		Source: name,
 		Status: subagentFinished,
 	}, test.events.LastEvent("work"))
-	require.Equal(t, "subagent "+name+" started\nsubagent "+name+" done after 0s\n", test.logs.String())
+
+	require.Equal(t, "<6>subagent started name="+name+"\n<6>subagent done name="+name+" after=0s\n", test.logs.String())
 
 	var first, second *ModelFakeCall
 
@@ -178,7 +182,10 @@ func TestFullContextGivesAFailedReport(t *testing.T) {
 		if subagentTestCall(call) {
 			w.WriteHeader(http.StatusBadRequest)
 
-			_, _ = io.WriteString(w, subagentTestFullContext)
+			_, err := io.WriteString(w, subagentTestFullContext)
+			if err != nil {
+				panic(err)
+			}
 
 			return
 		}
@@ -193,11 +200,12 @@ func TestFullContextGivesAFailedReport(t *testing.T) {
 
 	name := test.events.Last("subagent")
 	require.Equal(t, []string{
-		"work: [" + name + "]\nfailed: create model response: model call: HTTP 400: " + subagentTestFullContext + "\n\nFull chat: zoom(\"" + name + "\")",
+		"work: [" + name + "]\nfailed: run worker chain: create model response: model call: HTTP 400: " + subagentTestFullContext + "\n\nFull chat: zoom(\"" + name + "\")",
 		"reply: It failed.",
 	}, test.Log(t))
+
 	require.Equal(t, subagentFailed, test.events.LastEvent("work").Status)
-	require.Equal(t, "subagent "+name+" started\nsubagent "+name+" failed after 0s: create model response: model call: HTTP 400: "+subagentTestFullContext+"\n", test.logs.String())
+	require.Equal(t, "<6>subagent started name="+name+"\n<3>subagent failed name="+name+" after=0s: run worker chain: create model response: model call: HTTP 400: "+subagentTestFullContext+"\n", test.logs.String())
 }
 
 func TestSubagentHasItsOwnEffortAndNoSpawn(t *testing.T) {
@@ -349,7 +357,7 @@ func TestTellToAFinishedSubagentGoesOnFromItsLog(t *testing.T) {
 	require.Equal(t, "work: "+subagentReport(name, []string{"Reply 2."}), test.Log(t)[2])
 
 	_, err = runs.Tell(t.Context(), "BlueFox", "Hello.")
-	require.EqualError(t, err, "no agent BlueFox")
+	require.EqualError(t, err, "open worker log: no agent BlueFox")
 }
 
 func TestStopEndsASubagentAndItsCommand(t *testing.T) {
@@ -383,8 +391,9 @@ func TestStopEndsASubagentAndItsCommand(t *testing.T) {
 		"note: Stopped by the user: " + name + ".",
 		"work: " + subagentReport(name, []string{"stopped"}),
 	}, test.Log(t))
+
 	require.Equal(t, subagentStopped, test.events.LastEvent("work").Status)
-	require.Equal(t, "subagent "+name+" started\nsubagent "+name+" stopped after 0s\n", test.logs.String())
+	require.Equal(t, "<6>subagent started name="+name+"\n<6>subagent stopped name="+name+" after=0s\n", test.logs.String())
 
 	log, err := subagent.Show()
 	require.NoError(t, err)
@@ -456,7 +465,7 @@ func TestRestartResumesTheCutSubagents(t *testing.T) {
 	require.NoError(t, err)
 
 	first := &TurnEventRecorder{}
-	loop, _, stop := subagentTestStart(t, agent, server, first)
+	loop, _, stop := subagentTestStart(t, agent, server, first, discardLog())
 	_, err = loop.runs.Spawn(t.Context(), []string{"Build the project."}, nil)
 	require.NoError(t, err)
 
@@ -474,7 +483,7 @@ func TestRestartResumesTheCutSubagents(t *testing.T) {
 	restarted.Store(true)
 
 	second := &TurnEventRecorder{}
-	loop, memory, stop := subagentTestStart(t, agent, server, second)
+	loop, memory, stop := subagentTestStart(t, agent, server, second, discardLog())
 	defer stop()
 
 	second.WaitFor(t, "idle", 1)
@@ -506,26 +515,58 @@ func TestRestartReportsASubagentThatCannotGoOn(t *testing.T) {
 	require.NoError(t, os.WriteFile(filepath.Join(agent.dir, subagentWorkFileName), []byte(`{"running": ["BlueFox"]}`), 0o600))
 
 	events := &TurnEventRecorder{}
-	_, memory, stop := subagentTestStart(t, agent, server, events)
+	logs := &SyncBuffer{}
+	_, memory, stop := subagentTestStart(t, agent, server, events, daemonTestLogger(logs))
 	defer stop()
 
 	events.WaitFor(t, "idle", 1)
 	require.Equal(t, []string{
 		"note: The daemon restarted, cutting BlueFox; nothing was lost: go on.",
-		"work: " + subagentReport("BlueFox", []string{"failed: no agent BlueFox"}),
+		"work: " + subagentReport("BlueFox", []string{"failed: open worker log: no agent BlueFox"}),
 		"reply: a line",
 	}, subagentTestChat(t, memory))
+
 	require.Equal(t, subagentFailed, events.LastEvent("work").Status)
+	require.Equal(t, "<3>subagent lost at restart name=BlueFox: open worker log: no agent BlueFox\n", logs.String())
 
 	data, err := os.ReadFile(filepath.Join(agent.dir, subagentWorkFileName))
 	require.NoError(t, err)
 	require.JSONEq(t, `{"running": []}`, string(data))
 }
 
+// subagentTestLastItem returns the last input item of call.
+func subagentTestLastItem(call ModelFakeCall) map[string]any {
+	input := call.body["input"].([]any)
+
+	return input[len(input)-1].(map[string]any)
+}
+
+// subagentTestCall tells if call is a call of a subagent.
+func subagentTestCall(call ModelFakeCall) bool {
+	instructions, _ := call.body["instructions"].(string)
+
+	return strings.HasPrefix(instructions, "You are a subagent")
+}
+
+// subagentTestText returns the text of the user message item, or "" for another
+// item.
+func subagentTestText(item map[string]any) string {
+	content, _ := item["content"].([]any)
+
+	var text strings.Builder
+
+	for _, part := range content {
+		value, _ := part.(map[string]any)["text"].(string)
+		text.WriteString(value)
+	}
+
+	return text.String()
+}
+
 // subagentTestStart runs a loop of agent with its memory and subagents in the
-// agent directory, as the daemon does. The returned function stops the loop
-// and closes the files.
-func subagentTestStart(t *testing.T, agent *Agent, server *ModelFake, events *TurnEventRecorder) (*TurnLoop, *Memory, func()) {
+// agent directory, as the daemon does. The returned function stops the loop and
+// closes the files.
+func subagentTestStart(t *testing.T, agent *Agent, server *ModelFake, events *TurnEventRecorder, logger *slog.Logger) (*TurnLoop, *Memory, func()) {
 	t.Helper()
 
 	agent.config.Workdir = t.TempDir()
@@ -536,7 +577,7 @@ func subagentTestStart(t *testing.T, agent *Agent, server *ModelFake, events *Tu
 	subagents := newSubagents(filepath.Join(agent.dir, subagentDirName), clock.Now, subagentNameRandom)
 	client := newModelClient(server.URL, ModelAPIKey(modelTestKey), agent.CacheKey(), filepath.Join(agent.dir, "usage.jsonl"))
 	whatsapp, _, _ := whatsappStartTest(t, t.TempDir(), clock)
-	loop, err := newTurnLoop(agent, memory, subagents, whatsapp, newTestSchedules(t, clock.Now), client, clock.Now, discardLog(), events.Add)
+	loop, err := newTurnLoop(agent, memory, subagents, whatsapp, newTestSchedules(t, clock.Now), client, clock.Now, logger, events.Add)
 	require.NoError(t, err)
 
 	ctx, cancel := context.WithCancel(t.Context())
@@ -553,8 +594,7 @@ func subagentTestStart(t *testing.T, agent *Agent, server *ModelFake, events *Tu
 	}
 }
 
-// subagentTestChat returns each message of the chat in memory as
-// "kind: text".
+// subagentTestChat returns each message of the chat in memory as "kind: text".
 func subagentTestChat(t *testing.T, memory *Memory) []string {
 	t.Helper()
 
@@ -569,32 +609,3 @@ func subagentTestChat(t *testing.T, memory *Memory) []string {
 
 	return lines
 }
-
-// subagentTestCall tells if call is a call of a subagent.
-func subagentTestCall(call ModelFakeCall) bool {
-	instructions, _ := call.body["instructions"].(string)
-
-	return strings.HasPrefix(instructions, "You are a subagent")
-}
-
-// subagentTestLastItem returns the last input item of call.
-func subagentTestLastItem(call ModelFakeCall) map[string]any {
-	input := call.body["input"].([]any)
-
-	return input[len(input)-1].(map[string]any)
-}
-
-// subagentTestText returns the text of the user message item, or "" for
-// another item.
-func subagentTestText(item map[string]any) string {
-	content, _ := item["content"].([]any)
-
-	var text strings.Builder
-
-	for _, part := range content {
-		value, _ := part.(map[string]any)["text"].(string)
-		text.WriteString(value)
-	}
-
-	return text.String()
-}