Log failed turns and the ends of subagents

A turn that ends with an error logs one line with the error that the
clients get, such as a needed login or HTTP 429, so that it is not lost
when no client is connected. An interrupt of the user or a stop of the
daemon logs nothing.

The end of each subagent run logs one line with the name of the
subagent: done, failed with the cause, or stopped by the user. A cut
subagent that cannot go on after a restart logs its cause too.

Issue: e4acfcb

diff --git a/daemon.go b/daemon.go
index 4c0f466d4d0b04b5a9b2d05e541947e0fb3b2117..3f67a0bd9f2198df8ea92f43a0ec09a569378b44 100644 (file)
--- a/daemon.go
+++ b/daemon.go
@@ -124,7 +124,7 @@ func daemon(ctx context.Context, out io.Writer) (err error) {
        }
 
        return daemonServe(ctx, listener, telegram, whatsapp, schedules, func(notify func(Event)) (*TurnLoop, error) {
        }
 
        return daemonServe(ctx, listener, telegram, whatsapp, schedules, func(notify func(Event)) (*TurnLoop, error) {

-               return newTurnLoop(agent, memory, subagents, whatsapp, schedules, client, time.Now, notify)
+               return newTurnLoop(agent, memory, subagents, whatsapp, schedules, client, time.Now, logger, notify)

        })
 }
 
        })
 }
 

diff --git a/daemon_start_helper_test.go b/daemon_start_helper_test.go
index 6e4e32860ee944d3454cfa2408656537068f6d88..0c25acc01dff4b8fa93cddd9c43f7d799d3a4a6e 100644 (file)
--- a/daemon_start_helper_test.go
+++ b/daemon_start_helper_test.go
@@ -2,6 +2,8 @@ package main
 
 import (
        "context"
 
 import (
        "context"

+       "io"
+       "log"

        "path/filepath"
        "testing"
        "time"
        "path/filepath"
        "testing"
        "time"


@@ -52,7 +54,7 @@ func daemonStartTestWithSchedules(t *testing.T, server *ModelFake, bot *Telegram
        done := make(chan error)
        go func() {
                done <- daemonServe(ctx, listener, bot, whatsapp, schedules, func(notify func(Event)) (*TurnLoop, error) {
        done := make(chan error)
        go func() {
                done <- daemonServe(ctx, listener, bot, whatsapp, schedules, func(notify func(Event)) (*TurnLoop, error) {

-                       return newTurnLoop(agent, memory, newTestSubagents(t), whatsapp, schedules, client, clock, notify)
+                       return newTurnLoop(agent, memory, newTestSubagents(t), whatsapp, schedules, client, clock, log.New(io.Discard, "", 0), notify)

                })
        }()
 
                })
        }()
 

diff --git a/subagent_run.go b/subagent_run.go
index 16cf2bd03340a7271c985859f739777811810b46..7d3687c48f08691aed53f590dab7d10023e39e34 100644 (file)
--- a/subagent_run.go
+++ b/subagent_run.go
@@ -5,6 +5,7 @@ import (
        "encoding/json"
        "errors"
        "fmt"
        "encoding/json"
        "errors"
        "fmt"

+       "log"

        "maps"
        "os"
        "path/filepath"
        "maps"
        "os"
        "path/filepath"


@@ -43,9 +44,10 @@ var errSubagentClosed = errors.New("the daemon stops, so no subagent starts")
 // of the subagent. A message of Tell that comes during a chain joins its next
 // request after the tool results. One that comes after the final answer starts
 // one more chain, which reads the log again. The report of the run goes to
 // of the subagent. A message of Tell that comes during a chain joins its next
 // request after the tool results. One that comes after the final answer starts
 // one more chain, which reads the log again. The report of the run goes to

-// report: the final answer of each chain, or the error of a failed call. Stop
-// ends one run, and its report says that it stopped. At the stop of the daemon
-// the runs end with no report.
+// report: the final answer of each chain, or the error of a failed call. The
+// logger gets one line at the end of a run: done, failed with the cause, or
+// stopped. Stop ends one run, and its report says that it stopped. At the stop
+// of the daemon the runs end with no report.

 //
 // work.json in the directory of the agent holds the names of the running
 // subagents. Each start and each end of a run writes it whole, but Close does
 //
 // work.json in the directory of the agent holds the names of the running
 // subagents. Each start and each end of a run writes it whole, but Close does


@@ -66,6 +68,7 @@ type SubagentRuns struct {
        report    func(name, text, status string)
        note      func(text string) error
        fail      func(err error)
        report    func(name, text, status string)
        note      func(text string) error
        fail      func(err error)

+       logger    *log.Logger

        notify    func(Event)
 
        mutex   sync.Mutex
        notify    func(Event)
 
        mutex   sync.Mutex


@@ -237,6 +240,7 @@ func (r *SubagentRuns) Resume(ctx context.Context) error {
        for _, name := range names {
                _, err = r.Tell(ctx, name, text)
                if err != nil {
        for _, name := range names {
                _, err = r.Tell(ctx, name, text)
                if err != nil {

+                       r.logger.Printf("subagent %s cannot go on after the restart, and its report tells the agent: %v", name, err)

                        r.report(name, subagentReport(name, []string{"failed: " + err.Error()}), subagentFailed)
                }
        }
                        r.report(name, subagentReport(name, []string{"failed: " + err.Error()}), subagentFailed)
                }
        }


@@ -406,6 +410,7 @@ func (r *SubagentRuns) run(ctx context.Context, run *SubagentRun) {
        defer run.cancel()
 
        var replies []string
        defer run.cancel()
 
        var replies []string

+       var failure error

        stopped := false
        status := subagentFinished
        for more := true; more; {
        stopped := false
        status := subagentFinished
        for more := true; more; {


@@ -419,6 +424,7 @@ func (r *SubagentRuns) run(ctx context.Context, run *SubagentRun) {
                case err != nil:
                        reply = "failed: " + err.Error()
                        status = subagentFailed
                case err != nil:
                        reply = "failed: " + err.Error()
                        status = subagentFailed

+                       failure = err

                }
 
                more = err == nil && ctx.Err() == nil && len(run.pending) > 0
                }
 
                more = err == nil && ctx.Err() == nil && len(run.pending) > 0


@@ -447,6 +453,15 @@ func (r *SubagentRuns) run(ctx context.Context, run *SubagentRun) {
                status = subagentStopped
        }
 
                status = subagentStopped
        }
 

+       switch status {
+       case subagentStopped:
+               r.logger.Printf("subagent %s is stopped by the user", run.subagent.name)
+       case subagentFailed:
+               r.logger.Printf("subagent %s failed, and its report tells the agent: %v", run.subagent.name, failure)
+       default:
+               r.logger.Printf("subagent %s is done, and its report goes to the agent", run.subagent.name)
+       }
+

        r.report(run.subagent.name, subagentReport(run.subagent.name, replies), status)
 }
 
        r.report(run.subagent.name, subagentReport(run.subagent.name, replies), status)
 }
 

diff --git a/subagent_run_test.go b/subagent_run_test.go
index 02ad961f6b879142bbca77d38c865006f49ca368..a59b499eae015a037baf3daee59dce13cfda8a28 100644 (file)
--- a/subagent_run_test.go
+++ b/subagent_run_test.go
@@ -3,6 +3,7 @@ package main
 import (
        "context"
        "io"
 import (
        "context"
        "io"

+       "log"

        "net/http"
        "os"
        "path/filepath"
        "net/http"
        "os"
        "path/filepath"


@@ -66,6 +67,7 @@ func TestSpawnRunsASubagentInTheBackground(t *testing.T) {
                Source: name,
                Status: subagentFinished,
        }, test.events.LastEvent("work"))
                Source: name,
                Status: subagentFinished,
        }, test.events.LastEvent("work"))

+       require.Equal(t, "subagent "+name+" is done, and its report goes to the agent\n", test.logs.String())

 
        var first, second *ModelFakeCall
        for n := range server.Calls() {
 
        var first, second *ModelFakeCall
        for n := range server.Calls() {


@@ -188,6 +190,7 @@ func TestFullContextGivesAFailedReport(t *testing.T) {
                "reply: It failed.",
        }, test.Log(t))
        require.Equal(t, subagentFailed, test.events.LastEvent("work").Status)
                "reply: It failed.",
        }, test.Log(t))
        require.Equal(t, subagentFailed, test.events.LastEvent("work").Status)

+       require.Equal(t, "subagent "+name+" failed, and its report tells the agent: model call: HTTP 400: "+subagentTestFullContext+"\n", test.logs.String())

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


@@ -372,6 +375,7 @@ func TestStopEndsASubagentAndItsCommand(t *testing.T) {
                "work: " + subagentReport(name, []string{"stopped"}),
        }, test.Log(t))
        require.Equal(t, subagentStopped, test.events.LastEvent("work").Status)
                "work: " + subagentReport(name, []string{"stopped"}),
        }, test.Log(t))
        require.Equal(t, subagentStopped, test.events.LastEvent("work").Status)

+       require.Equal(t, "subagent "+name+" is stopped by the user\n", test.logs.String())

 
        log, err := subagent.Show()
        require.NoError(t, err)
 
        log, err := subagent.Show()
        require.NoError(t, err)


@@ -517,7 +521,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)
        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, events.Add)
+       loop, err := newTurnLoop(agent, memory, subagents, whatsapp, newTestSchedules(t, clock.Now), client, clock.Now, log.New(io.Discard, "", 0), events.Add)

        require.NoError(t, err)
 
        ctx, cancel := context.WithCancel(t.Context())
        require.NoError(t, err)
 
        ctx, cancel := context.WithCancel(t.Context())

diff --git a/turn.go b/turn.go
index 837ac7c519ecbdd6760bdbc370c7522a622f5422..e490068659da9fc4194a4f6eeb04a851ac464dee 100644 (file)
--- a/turn.go
+++ b/turn.go
@@ -4,6 +4,7 @@ import (
        "context"
        "errors"
        "fmt"
        "context"
        "errors"
        "fmt"

+       "log"

        "path/filepath"
        "sync"
        "time"
        "path/filepath"
        "sync"
        "time"


@@ -11,8 +12,9 @@ import (
 
 // newTurnLoop returns the loop of agent with its memory, its subagents, and the
 // WhatsApp link and the schedules of its tools. Its calls go through client,
 
 // newTurnLoop returns the loop of agent with its memory, its subagents, and the
 // WhatsApp link and the schedules of its tools. Its calls go through client,

-// and notify gets each event. The clock gives the date of a turn.
-func newTurnLoop(agent *Agent, memory *Memory, subagents *Subagents, whatsapp *WhatsApp, schedules *Schedules, client ChainClient, clock func() time.Time, notify func(Event)) (*TurnLoop, error) {
+// and notify gets each event. The clock gives the date of a turn. logger gets
+// the failed turns and the ends of the subagents.
+func newTurnLoop(agent *Agent, memory *Memory, subagents *Subagents, whatsapp *WhatsApp, schedules *Schedules, client ChainClient, clock func() time.Time, logger *log.Logger, notify func(Event)) (*TurnLoop, error) {

        layout, err := loadViewLayout(filepath.Join(agent.dir, viewLayoutFileName))
        if err != nil {
                return nil, err
        layout, err := loadViewLayout(filepath.Join(agent.dir, viewLayoutFileName))
        if err != nil {
                return nil, err


@@ -24,6 +26,7 @@ func newTurnLoop(agent *Agent, memory *Memory, subagents *Subagents, whatsapp *W
                client: client,
                layout: layout,
                clock:  clock,
                client: client,
                layout: layout,
                clock:  clock,

+               logger: logger,

                notify: notify,
                wake:   make(chan struct{}, 1),
        }
                notify: notify,
                wake:   make(chan struct{}, 1),
        }


@@ -38,6 +41,7 @@ func newTurnLoop(agent *Agent, memory *Memory, subagents *Subagents, whatsapp *W
                report:    l.Report,
                note:      l.note,
                fail:      l.fail,
                report:    l.Report,
                note:      l.note,
                fail:      l.fail,

+               logger:    logger,

                notify:    notify,
                running:   make(map[string]*SubagentRun),
        }
                notify:    notify,
                running:   make(map[string]*SubagentRun),
        }


@@ -88,6 +92,7 @@ type TurnLoop struct {
        runs   *SubagentRuns
        layout *ViewLayout
        clock  func() time.Time
        runs   *SubagentRuns
        layout *ViewLayout
        clock  func() time.Time

+       logger *log.Logger

        notify func(Event)
        wake   chan struct{}
 
        notify func(Event)
        wake   chan struct{}
 


@@ -298,9 +303,11 @@ func (l *TurnLoop) failed() error {
 }
 
 // turn runs one turn. A failed or interrupted model call ends the turn and
 }
 
 // turn runs one turn. A failed or interrupted model call ends the turn and

-// tells the clients. The messages of the turn stay in the log and the view, and
-// the next turn starts only with a new message, so a lasting failure such as a
-// needed login does not repeat. Only a failed log write is an error of turn.
+// tells the clients. A failure also goes to the logger, so that it is not lost
+// when no client is connected, but an interrupt does not. The messages of the
+// turn stay in the log and the view, and the next turn starts only with a new
+// message, so a lasting failure such as a needed login does not repeat. Only a
+// failed log write is an error of turn.

 func (l *TurnLoop) turn(ctx context.Context) error {
        ctx, cancel := context.WithCancel(ctx)
        defer cancel()
 func (l *TurnLoop) turn(ctx context.Context) error {
        ctx, cancel := context.WithCancel(ctx)
        defer cancel()


@@ -321,6 +328,10 @@ func (l *TurnLoop) turn(ctx context.Context) error {
 
        err := l.chain(ctx)
        if err != nil && !errors.Is(err, errChainLogWrite) {
 
        err := l.chain(ctx)
        if err != nil && !errors.Is(err, errChainLogWrite) {

+               if ctx.Err() == nil {
+                       l.logger.Printf("the turn stops before its end, and the agent waits for the next message: %v", err)
+               }
+

                l.notify(Event{
                        Kind: "error",
                        Text: turnError(ctx, err),
                l.notify(Event{
                        Kind: "error",
                        Text: turnError(ctx, err),

diff --git a/turn_test.go b/turn_test.go
index 1d958565550ba81be1fdfb4790460a3d7ac9d1ca..3cb15b280687b891043f7f255a5346f935647f82 100644 (file)
--- a/turn_test.go
+++ b/turn_test.go
@@ -4,6 +4,7 @@ import (
        "context"
        "encoding/json"
        "errors"
        "context"
        "encoding/json"
        "errors"

+       "log"

        "net/http"
        "path/filepath"
        "strings"
        "net/http"
        "path/filepath"
        "strings"


@@ -203,6 +204,7 @@ func TestInterruptEndsTheTurn(t *testing.T) {
        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) {


@@ -219,6 +221,10 @@ func TestFailedCallEndsTheTurnWithoutARetry(t *testing.T) {
        time.Sleep(50 * time.Millisecond)
        require.Equal(t, 1, server.Calls())
        require.Contains(t, test.events.Last("error"), "HTTP 503")
        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) {
 }
 
 func TestViewMessagesOnlyGrowBetweenTurns(t *testing.T) {


@@ -250,6 +256,7 @@ type TurnTestLoop struct {
        memory    *Memory
        loop      *TurnLoop
        events    *TurnEventRecorder
        memory    *Memory
        loop      *TurnLoop
        events    *TurnEventRecorder

+       logs      *SyncBuffer

        usagePath string
 }
 
        usagePath string
 }
 


@@ -387,12 +394,13 @@ func newTestTurnLoopWith(t *testing.T, server *ModelFake, summarizer Summarizer)
                agent:     agent,
                memory:    memory,
                events:    &TurnEventRecorder{},
                agent:     agent,
                memory:    memory,
                events:    &TurnEventRecorder{},

+               logs:      &SyncBuffer{},

                usagePath: filepath.Join(t.TempDir(), "usage.jsonl"),
        }
 
        client := newModelClient(server.URL, ModelAPIKey(modelTestKey), agent.CacheKey(), test.usagePath)
        whatsapp, _, _ := whatsappStartTest(t, t.TempDir(), clock)
                usagePath: filepath.Join(t.TempDir(), "usage.jsonl"),
        }
 
        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, test.events.Add)
+       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)
        require.NoError(t, err)
        ctx, cancel := context.WithCancel(t.Context())
        done := make(chan error)