From: Anderson A. Giacomolli Date: Mon, 9 Nov 2026 13:28:15 +0000 (-0300) Subject: Log failed turns and the ends of subagents X-Git-Url: http://git.giacomolli.uk/onechat/commitdiff_plain/5b778ad04422dd456b7d673fb653f0353c47b0fe?hp=8d9547f6e7ffa1e95ad25d9f8f2e7cfd23d992d0 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 4c0f466..3f67a0b 100644 --- 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 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 6e4e328..0c25acc 100644 --- a/daemon_start_helper_test.go +++ b/daemon_start_helper_test.go @@ -2,6 +2,8 @@ package main import ( "context" + "io" + "log" "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) { - 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 16cf2bd..7d3687c 100644 --- a/subagent_run.go +++ b/subagent_run.go @@ -5,6 +5,7 @@ import ( "encoding/json" "errors" "fmt" + "log" "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 -// 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 @@ -66,6 +68,7 @@ type SubagentRuns struct { report func(name, text, status string) note func(text string) error fail func(err error) + logger *log.Logger 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 { + 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) } } @@ -406,6 +410,7 @@ func (r *SubagentRuns) run(ctx context.Context, run *SubagentRun) { defer run.cancel() var replies []string + var failure error 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 + failure = err } 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 } + 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) } diff --git a/subagent_run_test.go b/subagent_run_test.go index 02ad961..a59b499 100644 --- a/subagent_run_test.go +++ b/subagent_run_test.go @@ -3,6 +3,7 @@ package main import ( "context" "io" + "log" "net/http" "os" "path/filepath" @@ -66,6 +67,7 @@ func TestSpawnRunsASubagentInTheBackground(t *testing.T) { 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() { @@ -188,6 +190,7 @@ func TestFullContextGivesAFailedReport(t *testing.T) { "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) { @@ -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) + require.Equal(t, "subagent "+name+" is stopped by the user\n", test.logs.String()) 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) - 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()) diff --git a/turn.go b/turn.go index 837ac7c..e490068 100644 --- a/turn.go +++ b/turn.go @@ -4,6 +4,7 @@ import ( "context" "errors" "fmt" + "log" "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, -// 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 @@ -24,6 +26,7 @@ func newTurnLoop(agent *Agent, memory *Memory, subagents *Subagents, whatsapp *W client: client, layout: layout, clock: clock, + logger: logger, 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, + logger: logger, notify: notify, running: make(map[string]*SubagentRun), } @@ -88,6 +92,7 @@ type TurnLoop struct { runs *SubagentRuns layout *ViewLayout clock func() time.Time + logger *log.Logger 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 -// 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() @@ -321,6 +328,10 @@ func (l *TurnLoop) turn(ctx context.Context) error { 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), diff --git a/turn_test.go b/turn_test.go index 1d95856..3cb15b2 100644 --- a/turn_test.go +++ b/turn_test.go @@ -4,6 +4,7 @@ import ( "context" "encoding/json" "errors" + "log" "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.Empty(t, test.logs.String()) } 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") + 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) { @@ -250,6 +256,7 @@ type TurnTestLoop struct { memory *Memory loop *TurnLoop events *TurnEventRecorder + logs *SyncBuffer usagePath string } @@ -387,12 +394,13 @@ func newTestTurnLoopWith(t *testing.T, server *ModelFake, summarizer Summarizer) 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) - 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)