Keep time limits with their operations

[onechat] / subagent_run_test.go

diff --git a/subagent_run_test.go b/subagent_run_test.go
index 125ca332cf12c94c3df00c4e994858735e6cc525..c5ad2995931a147424fc4ea3d86e27db31281530 100644 (file)
--- 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"
@@ -21,7 +22,9 @@ const subagentTestFullContext = `{"error": {"message": "Your input exceeds the c
 
 func TestSpawnRunsASubagentInTheBackground(t *testing.T) {
        server := newModelFake(t)
+
        var test *TurnTestLoop
+
        server.reply = func(w http.ResponseWriter, call ModelFakeCall) {
                last := subagentTestLastItem(call)
                switch {
@@ -47,6 +50,7 @@ func TestSpawnRunsASubagentInTheBackground(t *testing.T) {
 
        name := test.events.Last("subagent")
        require.True(t, subagentNameValid(name), name)
+
        work := filepath.Join(test.loop.runs.subagents.dir, name, "work")
        require.DirExists(t, work)
 
@@ -66,9 +70,10 @@ func TestSpawnRunsASubagentInTheBackground(t *testing.T) {
                Source: name,
                Status: subagentFinished,
        }, test.events.LastEvent("work"))
-       require.Equal(t, "subagent "+name+" done\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
+
        for n := range server.Calls() {
                call := server.Call(n)
                if !subagentTestCall(call) {
@@ -97,6 +102,7 @@ func TestSpawnRunsASubagentInTheBackground(t *testing.T) {
        require.Equal(t, instructions, first.body["instructions"])
 
        var tools []string
+
        for _, tool := range first.body["tools"].([]any) {
                tools = append(tools, tool.(map[string]any)["name"].(string))
        }
@@ -112,6 +118,7 @@ func TestSpawnRunsASubagentInTheBackground(t *testing.T) {
        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)
 
        var agents []string
+
        for _, record := range modelReadUsage(t, test.usagePath) {
                agents = append(agents, record.Agent)
        }
@@ -140,6 +147,7 @@ func TestReportJoinsTheNextRequestOfARunningTurn(t *testing.T) {
        require.NoError(t, err)
 
        <-arrived
+
        report := subagentReport("GreenOtter", []string{"It is done."})
        test.loop.Report("GreenOtter", report, subagentFinished)
        close(release)
@@ -170,6 +178,7 @@ func TestFullContextGivesAFailedReport(t *testing.T) {
        server.reply = func(w http.ResponseWriter, call ModelFakeCall) {
                if subagentTestCall(call) {
                        w.WriteHeader(http.StatusBadRequest)
+
                        _, _ = io.WriteString(w, subagentTestFullContext)
 
                        return
@@ -185,11 +194,11 @@ func TestFullContextGivesAFailedReport(t *testing.T) {
 
        name := test.events.Last("subagent")
        require.Equal(t, []string{
-               "work: [" + name + "]\nfailed: model call: HTTP 400: " + subagentTestFullContext + "\n\nFull chat: zoom(\"" + name + "\")",
+               "work: [" + name + "]\nfailed: 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+" failed: 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: create model response: model call: HTTP 400: "+subagentTestFullContext+"\n", test.logs.String())
 }
 
 func TestSubagentHasItsOwnEffortAndNoSpawn(t *testing.T) {
@@ -260,6 +269,7 @@ func TestTellReachesARunningSubagentBetweenItsToolCalls(t *testing.T) {
        require.NoError(t, err)
 
        <-arrived
+
        name := test.events.Last("subagent")
        output, err := runs.Tell(t.Context(), name, "Use the second disk.")
        require.NoError(t, err)
@@ -294,6 +304,7 @@ func TestTellAfterTheFinalAnswerStartsAnotherChain(t *testing.T) {
        require.NoError(t, err)
 
        <-arrived
+
        name := test.events.Last("subagent")
        _, err = runs.Tell(t.Context(), name, "Count again.")
        require.NoError(t, err)
@@ -344,7 +355,7 @@ func TestTellToAFinishedSubagentGoesOnFromItsLog(t *testing.T) {
 
 func TestStopEndsASubagentAndItsCommand(t *testing.T) {
        server := newModelFake(t)
-       server.reply = func(w http.ResponseWriter, call ModelFakeCall) {
+       server.reply = func(w http.ResponseWriter, _ ModelFakeCall) {
                modelWriteEvents(w, modelCompletedEvent([]any{modelFunctionCallItem("fc_1", "call_1", "shell", `{"command":"touch started && sleep 30"}`)}, 100, 0, 5))
        }
 
@@ -374,7 +385,7 @@ func TestStopEndsASubagentAndItsCommand(t *testing.T) {
                "work: " + subagentReport(name, []string{"stopped"}),
        }, test.Log(t))
        require.Equal(t, subagentStopped, test.events.LastEvent("work").Status)
-       require.Equal(t, "subagent "+name+" stopped\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)
@@ -396,7 +407,7 @@ func TestCloseEndsTheSubagentsWithNoReport(t *testing.T) {
                close(release)
        })
 
-       server.reply = func(w http.ResponseWriter, call ModelFakeCall) {
+       server.reply = func(_ http.ResponseWriter, _ ModelFakeCall) {
                close(arrived)
                <-release
        }
@@ -428,10 +439,12 @@ func TestRestartResumesTheCutSubagents(t *testing.T) {
        })
 
        var restarted atomic.Bool
+
        server.reply = func(w http.ResponseWriter, call ModelFakeCall) {
                switch {
                case subagentTestCall(call) && !restarted.Load():
                        arrived <- struct{}{}
+
                        <-release
                case subagentTestCall(call):
                        modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem("Built.")}, 100, 0, 5))
@@ -444,12 +457,14 @@ 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)
 
        <-arrived
+
        name := first.Last("subagent")
+
        stop()
        require.Zero(t, first.Count("work"))
 
@@ -458,11 +473,13 @@ func TestRestartResumesTheCutSubagents(t *testing.T) {
        require.JSONEq(t, `{"running": ["`+name+`"]}`, string(data))
 
        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)
+
        note := "The daemon restarted, cutting " + name + "; nothing was lost: go on."
        log := subagentTestChat(t, memory)
        require.Equal(t, []string{
@@ -490,7 +507,8 @@ 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)
@@ -500,6 +518,7 @@ func TestRestartReportsASubagentThatCannotGoOn(t *testing.T) {
                "reply: a line",
        }, subagentTestChat(t, memory))
        require.Equal(t, subagentFailed, events.LastEvent("work").Status)
+       require.Equal(t, "<3>subagent lost at restart name=BlueFox: no agent BlueFox\n", logs.String())
 
        data, err := os.ReadFile(filepath.Join(agent.dir, subagentWorkFileName))
        require.NoError(t, err)
@@ -509,7 +528,7 @@ func TestRestartReportsASubagentThatCannotGoOn(t *testing.T) {
 // 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()) {
+func subagentTestStart(t *testing.T, agent *Agent, server *ModelFake, events *TurnEventRecorder, logger *slog.Logger) (*TurnLoop, *Memory, func()) {
        t.Helper()
 
        agent.config.Workdir = t.TempDir()
@@ -520,7 +539,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())
@@ -543,6 +562,7 @@ func subagentTestChat(t *testing.T, memory *Memory) []string {
        t.Helper()
 
        var lines []string
+
        for id := range memory.Len() {
                message, err := memory.Message(id)
                require.NoError(t, err)
@@ -571,7 +591,9 @@ func subagentTestLastItem(call ModelFakeCall) map[string]any {
 // 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)