Log each schedule run by its ID

[onechat] / turn_test.go

diff --git a/turn_test.go b/turn_test.go
index 1b179406b72bb087fcfce2db11f39ccac1970006..3cb15b280687b891043f7f255a5346f935647f82 100644 (file)
--- a/turn_test.go
+++ b/turn_test.go
@@ -2,8 +2,11 @@ package main
 
 import (
        "context"
 
 import (
        "context"

+       "encoding/json"

        "errors"
        "errors"

+       "log"

        "net/http"
        "net/http"

+       "path/filepath"

        "strings"
        "sync"
        "testing"
        "strings"
        "sync"
        "testing"


@@ -13,22 +16,22 @@ import (
 )
 
 func TestTurnRunsToolsUntilTheFinalAnswer(t *testing.T) {
 )
 
 func TestTurnRunsToolsUntilTheFinalAnswer(t *testing.T) {

-       server := newFakeResponses(t)
-       server.reply = func(w http.ResponseWriter, call fakeCall) {
+       server := newModelFake(t)
+       server.reply = func(w http.ResponseWriter, call ModelFakeCall) {

                if call.number == 0 {
                if call.number == 0 {

-                       writeEvents(w, completedEvent([]any{
-                               reasoningItem("rs_1", "opaque thought"),
-                               functionCallItem("fc_1", "call_1", "shell", `{"command":"echo hi"}`),
+                       modelWriteEvents(w, modelCompletedEvent([]any{
+                               modelReasoningItem("rs_1", "opaque thought"),
+                               modelFunctionCallItem("fc_1", "call_1", "shell", `{"command":"echo hi"}`),

                        }, 100, 0, 5))
 
                        return
                }
 
                        }, 100, 0, 5))
 
                        return
                }
 

-               writeEvents(w, completedEvent([]any{messageItem("It said hi.")}, 120, 100, 5))
+               modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem("It said hi.")}, 120, 100, 5))

        }
 
        }
 

-       test := newTestLoop(t, server)
-       _, err := test.loop.Submit("Run echo hi.")
+       test := newTestTurnLoop(t, server)
+       _, err := test.loop.Submit(terminalSource, "Run echo hi.")

        require.NoError(t, err)
        test.events.WaitFor(t, "idle", 1)
        require.Equal(t, 2, server.Calls())
        require.NoError(t, err)
        test.events.WaitFor(t, "idle", 1)
        require.Equal(t, 2, server.Calls())


@@ -57,47 +60,54 @@ func TestTurnRunsToolsUntilTheFinalAnswer(t *testing.T) {
                "reply: It said hi.",
        }, test.Log(t))
        require.Equal(t, []string{"user", "busy", "tool", "echo", "reply", "idle"}, test.events.Kinds())
                "reply: It said hi.",
        }, test.Log(t))
        require.Equal(t, []string{"user", "busy", "tool", "echo", "reply", "idle"}, test.events.Kinds())

+
+       var turns []string
+       for _, record := range modelReadUsage(t, test.usagePath) {
+               turns = append(turns, record.Turn)
+       }
+
+       require.Equal(t, []string{"first", "next"}, turns)

 }
 
 func TestFirstRequestHoldsTheViewTheStateAndTheMessage(t *testing.T) {
 }
 
 func TestFirstRequestHoldsTheViewTheStateAndTheMessage(t *testing.T) {

-       server := newFakeResponses(t)
-       test := newTestLoop(t, server)
+       server := newModelFake(t)
+       test := newTestTurnLoop(t, server)

        _, err := test.memory.Append("user", "an earlier message")
        require.NoError(t, err)
 
        _, err := test.memory.Append("user", "an earlier message")
        require.NoError(t, err)
 

-       _, err = test.loop.Submit("The new message.")
+       _, err = test.loop.Submit(terminalSource, "The new message.")

        require.NoError(t, err)
        test.events.WaitFor(t, "idle", 1)
 
        require.Equal(t, []string{
        require.NoError(t, err)
        test.events.WaitFor(t, "idle", 1)
 
        require.Equal(t, []string{

-               "<chat>\n0+1|user: an earlier message\n</chat>\n",
-               "Now: Thursday 2026-01-01 12:00 +00:00\n",
+               "<chat>\n0+1|user: an earlier message\n",
+               "</chat>\n\nNow: Thursday 2026-01-01 12:00 +00:00",

                "The new message.",
                "The new message.",

-       }, inputParts(t, server.Call(0)))
+       }, turnInputTexts(t, server.Call(0)))

 }
 
 func TestMessageDuringATurnJoinsTheNextRequest(t *testing.T) {
 }
 
 func TestMessageDuringATurnJoinsTheNextRequest(t *testing.T) {

-       server := newFakeResponses(t)
+       server := newModelFake(t)

        arrived := make(chan struct{})
        release := make(chan struct{})
        arrived := make(chan struct{})
        release := make(chan struct{})

-       server.reply = func(w http.ResponseWriter, call fakeCall) {
+       server.reply = func(w http.ResponseWriter, call ModelFakeCall) {

                if call.number == 0 {
                        close(arrived)
                        <-release
                if call.number == 0 {
                        close(arrived)
                        <-release

-                       writeEvents(w, completedEvent([]any{functionCallItem("fc_1", "call_1", "date", `{"id":0}`)}, 100, 0, 5))
+                       modelWriteEvents(w, modelCompletedEvent([]any{modelFunctionCallItem("fc_1", "call_1", "date", `{"id":0}`)}, 100, 0, 5))

 
                        return
                }
 
 
                        return
                }
 

-               writeEvents(w, completedEvent([]any{messageItem("done")}, 100, 0, 5))
+               modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem("done")}, 100, 0, 5))

        }
 
        }
 

-       test := newTestLoop(t, server)
-       _, err := test.loop.Submit("first")
+       test := newTestTurnLoop(t, server)
+       _, err := test.loop.Submit(terminalSource, "first")

        require.NoError(t, err)
 
        <-arrived
        require.NoError(t, err)
 
        <-arrived

-       _, err = test.loop.Submit("second, during the turn")
+       _, err = test.loop.Submit(terminalSource, "second, during the turn")

        require.NoError(t, err)
        close(release)
 
        require.NoError(t, err)
        close(release)
 


@@ -114,45 +124,45 @@ func TestMessageDuringATurnJoinsTheNextRequest(t *testing.T) {
 }
 
 func TestMessageDuringTheFinalRequestStartsANewTurn(t *testing.T) {
 }
 
 func TestMessageDuringTheFinalRequestStartsANewTurn(t *testing.T) {

-       server := newFakeResponses(t)
+       server := newModelFake(t)

        arrived := make(chan struct{})
        release := make(chan struct{})
        arrived := make(chan struct{})
        release := make(chan struct{})

-       server.reply = func(w http.ResponseWriter, call fakeCall) {
+       server.reply = func(w http.ResponseWriter, call ModelFakeCall) {

                if call.number == 0 {
                        close(arrived)
                        <-release
                }
 
                if call.number == 0 {
                        close(arrived)
                        <-release
                }
 

-               writeEvents(w, completedEvent([]any{messageItem("answer")}, 100, 0, 5))
+               modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem("answer")}, 100, 0, 5))

        }
 
        }
 

-       test := newTestLoop(t, server)
-       _, err := test.loop.Submit("first")
+       test := newTestTurnLoop(t, server)
+       _, err := test.loop.Submit(terminalSource, "first")

        require.NoError(t, err)
 
        <-arrived
        require.NoError(t, err)
 
        <-arrived

-       _, err = test.loop.Submit("second")
+       _, err = test.loop.Submit(terminalSource, "second")

        require.NoError(t, err)
        close(release)
 
        test.events.WaitFor(t, "idle", 2)
        require.Equal(t, 2, server.Calls())
 
        require.NoError(t, err)
        close(release)
 
        test.events.WaitFor(t, "idle", 2)
        require.Equal(t, 2, server.Calls())
 

-       parts := inputParts(t, server.Call(1))
-       require.Equal(t, "second", parts[len(parts)-1])
-       require.Contains(t, parts[0], "|reply: answer\n")
+       texts := turnInputTexts(t, server.Call(1))
+       require.Equal(t, "second", texts[len(texts)-1])
+       require.Contains(t, strings.Join(texts, ""), "|reply: answer\n")

 }
 
 func TestTurnWaitsForTheSummaries(t *testing.T) {
 }
 
 func TestTurnWaitsForTheSummaries(t *testing.T) {

-       server := newFakeResponses(t)
+       server := newModelFake(t)

        summarizer := newFakeSummarizer()
        summarizer.gate = make(chan struct{})
        summarizer := newFakeSummarizer()
        summarizer.gate = make(chan struct{})

-       test := newTestLoopWith(t, server, summarizer)
+       test := newTestTurnLoopWith(t, server, summarizer)

 
        _, err := test.memory.Append("echo", strings.Repeat("long output ", 100))
        require.NoError(t, err)
 
 
        _, err := test.memory.Append("echo", strings.Repeat("long output ", 100))
        require.NoError(t, err)
 

-       _, err = test.loop.Submit("go on")
+       _, err = test.loop.Submit(terminalSource, "go on")

        require.NoError(t, err)
 
        time.Sleep(50 * time.Millisecond)
        require.NoError(t, err)
 
        time.Sleep(50 * time.Millisecond)


@@ -161,24 +171,24 @@ func TestTurnWaitsForTheSummaries(t *testing.T) {
        close(summarizer.gate)
        test.events.WaitFor(t, "idle", 1)
        require.Equal(t, 1, server.Calls())
        close(summarizer.gate)
        test.events.WaitFor(t, "idle", 1)
        require.Equal(t, 1, server.Calls())

-       require.NotContains(t, inputParts(t, server.Call(0))[0], pending)
+       require.NotContains(t, turnInputTexts(t, server.Call(0))[0], viewPending)

 }
 
 func TestInterruptEndsTheTurn(t *testing.T) {
 }
 
 func TestInterruptEndsTheTurn(t *testing.T) {

-       server := newFakeResponses(t)
+       server := newModelFake(t)

        arrived := make(chan struct{})
        release := make(chan struct{})
        arrived := make(chan struct{})
        release := make(chan struct{})

-       server.reply = func(w http.ResponseWriter, call fakeCall) {
+       server.reply = func(w http.ResponseWriter, call ModelFakeCall) {

                if call.number == 0 {
                        close(arrived)
                        <-release
                }
 
                if call.number == 0 {
                        close(arrived)
                        <-release
                }
 

-               writeEvents(w, completedEvent([]any{messageItem("answer")}, 100, 0, 5))
+               modelWriteEvents(w, modelCompletedEvent([]any{modelMessageItem("answer")}, 100, 0, 5))

        }
 
        }
 

-       test := newTestLoop(t, server)
-       _, err := test.loop.Submit("a long task")
+       test := newTestTurnLoop(t, server)
+       _, err := test.loop.Submit(terminalSource, "a long task")

        require.NoError(t, err)
 
        <-arrived
        require.NoError(t, err)
 
        <-arrived


@@ -190,38 +200,68 @@ func TestInterruptEndsTheTurn(t *testing.T) {
        require.Equal(t, []string{"user: a long task"}, test.Log(t))
        require.False(t, test.loop.Interrupt())
 
        require.Equal(t, []string{"user: a long task"}, test.Log(t))
        require.False(t, test.loop.Interrupt())
 

-       _, err = test.loop.Submit("again")
+       _, err = test.loop.Submit(terminalSource, "again")

        require.NoError(t, err)
        test.events.WaitFor(t, "idle", 2)
        require.Equal(t, "reply: answer", test.Log(t)[2])
        require.NoError(t, err)
        test.events.WaitFor(t, "idle", 2)
        require.Equal(t, "reply: answer", test.Log(t)[2])

+       require.Empty(t, test.logs.String())

 }
 
 func TestFailedCallEndsTheTurnWithoutARetry(t *testing.T) {
 }
 
 func TestFailedCallEndsTheTurnWithoutARetry(t *testing.T) {

-       server := newFakeResponses(t)
-       server.reply = func(w http.ResponseWriter, call fakeCall) {
+       server := newModelFake(t)
+       server.reply = func(w http.ResponseWriter, call ModelFakeCall) {

                http.Error(w, "busy", http.StatusServiceUnavailable)
        }
 
                http.Error(w, "busy", http.StatusServiceUnavailable)
        }
 

-       test := newTestLoop(t, server)
-       _, err := test.loop.Submit("hello")
+       test := newTestTurnLoop(t, server)
+       _, err := test.loop.Submit(terminalSource, "hello")

        require.NoError(t, err)
        test.events.WaitFor(t, "idle", 1)
 
        time.Sleep(50 * time.Millisecond)
        require.Equal(t, 1, server.Calls())
        require.Contains(t, test.events.Last("error"), "HTTP 503")
        require.NoError(t, err)
        test.events.WaitFor(t, "idle", 1)
 
        time.Sleep(50 * time.Millisecond)
        require.Equal(t, 1, server.Calls())
        require.Contains(t, test.events.Last("error"), "HTTP 503")

+       require.Equal(t, 1, strings.Count(test.logs.String(), "\n"))
+       require.Contains(t, test.logs.String(), "the turn stops before its end, and the agent waits for the next message: ")
+       require.Contains(t, test.logs.String(), "HTTP 503")
+       require.NotContains(t, test.logs.String(), "hello")
+}
+
+func TestViewMessagesOnlyGrowBetweenTurns(t *testing.T) {
+       server := newModelFake(t)
+       test := newTestTurnLoop(t, server)
+       for n, text := range []string{"one", "two", "three"} {
+               _, err := test.loop.Submit(terminalSource, text)
+               require.NoError(t, err)
+               test.events.WaitFor(t, "idle", n+1)
+       }
+
+       first := server.Call(1).body["input"].([]any)
+       second := server.Call(2).body["input"].([]any)
+       require.Len(t, first, 4)
+       require.Len(t, second, 5)
+       require.Equal(t, first[:2], second[:2])
+       require.Equal(t, []string{
+               "<chat>\n",
+               "0+1|user: one\n1+1|reply: a line\n",
+               "2+1|user: two\n3+1|reply: a line\n",
+               "</chat>\n\nNow: Thursday 2026-01-01 12:00 +00:00",
+               "three",
+       }, turnInputTexts(t, server.Call(2)))

 }
 
 }
 

-// testLoop is a loop that runs in the background of a test, with its parts.
-type testLoop struct {
-       agent  *Agent
-       memory *Memory
-       loop   *loop
-       events *eventRecorder
+// TurnTestLoop is a loop that runs in the background of a test, with its parts.
+type TurnTestLoop struct {
+       agent     *Agent
+       memory    *Memory
+       loop      *TurnLoop
+       events    *TurnEventRecorder
+       logs      *SyncBuffer
+       usagePath string

 }
 
 // Log returns the logged messages as "kind: text".
 }
 
 // Log returns the logged messages as "kind: text".

-func (l *testLoop) Log(t *testing.T) []string {
+func (l *TurnTestLoop) Log(t *testing.T) []string {

        t.Helper()
 
        var lines []string
        t.Helper()
 
        var lines []string


@@ -235,20 +275,22 @@ func (l *testLoop) Log(t *testing.T) []string {
        return lines
 }
 
        return lines
 }
 

-// eventRecorder keeps the events of a loop.
-type eventRecorder struct {
+// TurnEventRecorder keeps the events of a loop.
+type TurnEventRecorder struct {

        mutex  sync.Mutex
        events []Event
 }
 
        mutex  sync.Mutex
        events []Event
 }
 

-func (r *eventRecorder) Add(event Event) {
-       r.mutex.Lock()
-       defer r.mutex.Unlock()
+// WaitFor waits until count events of kind came.
+func (r *TurnEventRecorder) WaitFor(t *testing.T, kind string, count int) {
+       t.Helper()

 
 

-       r.events = append(r.events, event)
+       require.Eventually(t, func() bool {
+               return r.Count(kind) >= count
+       }, 10*time.Second, time.Millisecond)

 }
 
 }
 

-func (r *eventRecorder) Kinds() []string {
+func (r *TurnEventRecorder) Kinds() []string {

        r.mutex.Lock()
        defer r.mutex.Unlock()
 
        r.mutex.Lock()
        defer r.mutex.Unlock()
 


@@ -260,7 +302,7 @@ func (r *eventRecorder) Kinds() []string {
        return kinds
 }
 
        return kinds
 }
 

-func (r *eventRecorder) Count(kind string) int {
+func (r *TurnEventRecorder) Count(kind string) int {

        count := 0
        for _, each := range r.Kinds() {
                if each == kind {
        count := 0
        for _, each := range r.Kinds() {
                if each == kind {


@@ -272,37 +314,72 @@ func (r *eventRecorder) Count(kind string) int {
 }
 
 // Last returns the text of the last event of kind.
 }
 
 // Last returns the text of the last event of kind.

-func (r *eventRecorder) Last(kind string) string {
+func (r *TurnEventRecorder) Last(kind string) string {
+       return r.LastEvent(kind).Text
+}
+
+// LastEvent returns the last event of kind.
+func (r *TurnEventRecorder) LastEvent(kind string) Event {

        r.mutex.Lock()
        defer r.mutex.Unlock()
 
        for n := len(r.events) - 1; n >= 0; n-- {
                if r.events[n].Kind == kind {
        r.mutex.Lock()
        defer r.mutex.Unlock()
 
        for n := len(r.events) - 1; n >= 0; n-- {
                if r.events[n].Kind == kind {

-                       return r.events[n].Text
+                       return r.events[n]

                }
        }
 
                }
        }
 

-       return ""
+       return Event{}

 }
 
 }
 

-// WaitFor waits until count events of kind came.
-func (r *eventRecorder) WaitFor(t *testing.T, kind string, count int) {
+func (r *TurnEventRecorder) Add(event Event) {
+       r.mutex.Lock()
+       defer r.mutex.Unlock()
+
+       r.events = append(r.events, event)
+}
+
+func newTestTurnLoop(t *testing.T, server *ModelFake) *TurnTestLoop {

        t.Helper()
 
        t.Helper()
 

-       require.Eventually(t, func() bool {
-               return r.Count(kind) >= count
-       }, 10*time.Second, time.Millisecond)
+       return newTestTurnLoopWith(t, server, newFakeSummarizer())

 }
 
 }
 

-func newTestLoop(t *testing.T, server *fakeResponses) *testLoop {
+// turnInputTexts returns the text of each user message of the input of call.
+func turnInputTexts(t *testing.T, call ModelFakeCall) []string {

        t.Helper()
 
        t.Helper()
 

-       return newTestLoopWith(t, server, newFakeSummarizer())
+       var body struct {
+               Input []struct {
+                       Role    string `json:"role"`
+                       Content []struct {
+                               Text string `json:"text"`
+                       } `json:"content"`
+               } `json:"input"`
+       }
+
+       require.NoError(t, json.Unmarshal(call.raw, &body))
+
+       var texts []string
+       for _, item := range body.Input {
+               if item.Role != "user" {
+                       continue
+               }
+
+               var text strings.Builder
+               for _, part := range item.Content {
+                       text.WriteString(part.Text)
+               }
+
+               texts = append(texts, text.String())
+       }
+
+       return texts

 }
 
 }
 

-// newTestLoopWith returns a running loop on a new agent whose builds use
+// newTestTurnLoopWith returns a running loop on a new agent whose builds use

 // summarizer and whose commands run in a temporary directory.
 // summarizer and whose commands run in a temporary directory.

-func newTestLoopWith(t *testing.T, server *fakeResponses, summarizer Summarizer) *testLoop {
+func newTestTurnLoopWith(t *testing.T, server *ModelFake, summarizer Summarizer) *TurnTestLoop {

        t.Helper()
 
        agent, err := openAgent(t.TempDir())
        t.Helper()
 
        agent, err := openAgent(t.TempDir())


@@ -313,13 +390,18 @@ func newTestLoopWith(t *testing.T, server *fakeResponses, summarizer Summarizer)
        memory, err := openMemory(t.Context(), t.TempDir(), clock.Now, summarizer)
        require.NoError(t, err)
 
        memory, err := openMemory(t.Context(), t.TempDir(), clock.Now, summarizer)
        require.NoError(t, err)
 

-       test := &testLoop{
-               agent:  agent,
-               memory: memory,
-               events: &eventRecorder{},
+       test := &TurnTestLoop{
+               agent:     agent,
+               memory:    memory,
+               events:    &TurnEventRecorder{},
+               logs:      &SyncBuffer{},
+               usagePath: filepath.Join(t.TempDir(), "usage.jsonl"),

        }
 
        }
 

-       test.loop = newLoop(agent, memory, newTestClient(t, server), clock.Now, test.events.Add)
+       client := newModelClient(server.URL, ModelAPIKey(modelTestKey), agent.CacheKey(), test.usagePath)
+       whatsapp, _, _ := whatsappStartTest(t, t.TempDir(), clock)
+       test.loop, err = newTurnLoop(agent, memory, newTestSubagents(t), whatsapp, newTestSchedules(t, clock.Now), client, clock.Now, log.New(test.logs, "", 0), test.events.Add)
+       require.NoError(t, err)

        ctx, cancel := context.WithCancel(t.Context())
        done := make(chan error)
        go func() {
        ctx, cancel := context.WithCancel(t.Context())
        done := make(chan error)
        go func() {


@@ -334,22 +416,3 @@ func newTestLoopWith(t *testing.T, server *fakeResponses, summarizer Summarizer)
 
        return test
 }
 
        return test
 }

-
-func reasoningItem(id, encrypted string) map[string]any {
-       return map[string]any{
-               "type":              "reasoning",
-               "id":                id,
-               "encrypted_content": encrypted,
-               "summary":           []any{},
-       }
-}
-
-func functionCallItem(id, callID, name, arguments string) map[string]any {
-       return map[string]any{
-               "type":      "function_call",
-               "id":        id,
-               "call_id":   callID,
-               "name":      name,
-               "arguments": arguments,
-       }
-}