From d7a967f43fae27bcabc6072da3b5a2f923d47764 Mon Sep 17 00:00:00 2001 From: "Anderson A. Giacomolli" Date: Mon, 9 Nov 2026 14:41:53 -0300 Subject: [PATCH] Log the start and the length of each subagent run The journal shows when a subagent runs, so a hung run is visible, and the end line gives the length of the run. --- subagent_run.go | 21 +++++++++++++-------- subagent_run_test.go | 6 +++--- 2 files changed, 16 insertions(+), 11 deletions(-) diff --git a/subagent_run.go b/subagent_run.go index ca4ebd4..67cf79d 100644 --- a/subagent_run.go +++ b/subagent_run.go @@ -12,6 +12,7 @@ import ( "slices" "strings" "sync" + "time" ) const ( @@ -317,8 +318,8 @@ func (r *SubagentRuns) effort(subagent *Subagent) (string, error) { return "", fmt.Errorf("the log of %s does not start with a subagent note", subagent.name) } -// start runs run in the background. Its context keeps the values of ctx, but -// only Stop and Close end it. +// start runs run in the background and logs its start. Its context keeps the +// values of ctx, but only Stop and Close end it. func (r *SubagentRuns) start(ctx context.Context, run *SubagentRun) error { ctx, run.cancel = context.WithCancel(context.WithoutCancel(ctx)) @@ -348,6 +349,8 @@ func (r *SubagentRuns) start(ctx context.Context, run *SubagentRun) error { r.workers.Add(1) r.mutex.Unlock() + run.started = r.subagents.clock() + r.logger.Printf("subagent %s started", run.subagent.name) r.notify(Event{ Kind: "subagent", Text: run.subagent.name, @@ -402,8 +405,8 @@ func (r *SubagentRuns) workPath() string { return filepath.Join(r.agent.dir, subagentWorkFileName) } -// run runs the chains of run and reports its end, unless Close ended it. A -// chain follows while messages wait after the final answer of the chain before +// run runs the chains of run and reports and logs its end with the length of +// the run, unless Close ended it. A chain follows while messages wait after the final answer of the chain before // it, and no chain failed. A chain that Stop ends gives the reply "stopped". func (r *SubagentRuns) run(ctx context.Context, run *SubagentRun) { defer r.workers.Done() @@ -453,13 +456,14 @@ func (r *SubagentRuns) run(ctx context.Context, run *SubagentRun) { status = subagentStopped } + length := durationText(r.subagents.clock().Sub(run.started)) switch status { case subagentStopped: - r.logger.Printf("subagent %s stopped", run.subagent.name) + r.logger.Printf("subagent %s stopped after %s", run.subagent.name, length) case subagentFailed: - r.logger.Printf("subagent %s failed: %v", run.subagent.name, failure) + r.logger.Printf("subagent %s failed after %s: %v", run.subagent.name, length, failure) default: - r.logger.Printf("subagent %s done", run.subagent.name) + r.logger.Printf("subagent %s done after %s", run.subagent.name, length) } r.report(run.subagent.name, subagentReport(run.subagent.name, replies), status) @@ -520,7 +524,7 @@ func (r *SubagentRuns) take(run *SubagentRun) []Message { // SubagentRun is one run of a subagent: the view that its requests get, its // effort, the end of its context, the messages of Tell that wait for a request, -// and whether Stop ended it. The mutex of SubagentRuns protects the messages +// whether Stop ended it, and the time it started. The mutex of SubagentRuns protects the messages // and the stop. type SubagentRun struct { subagent *Subagent @@ -529,6 +533,7 @@ type SubagentRun struct { cancel context.CancelFunc pending []Message stopped bool + started time.Time } // SubagentWorkFile is the content of work.json. diff --git a/subagent_run_test.go b/subagent_run_test.go index 125ca33..a39d81c 100644 --- a/subagent_run_test.go +++ b/subagent_run_test.go @@ -66,7 +66,7 @@ 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, "subagent "+name+" started\nsubagent "+name+" done after 0s\n", test.logs.String()) var first, second *ModelFakeCall for n := range server.Calls() { @@ -189,7 +189,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: model call: HTTP 400: "+subagentTestFullContext+"\n", test.logs.String()) + require.Equal(t, "subagent "+name+" started\nsubagent "+name+" failed after 0s: model call: HTTP 400: "+subagentTestFullContext+"\n", test.logs.String()) } func TestSubagentHasItsOwnEffortAndNoSpawn(t *testing.T) { @@ -374,7 +374,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, "subagent "+name+" started\nsubagent "+name+" stopped after 0s\n", test.logs.String()) log, err := subagent.Show() require.NoError(t, err) -- 2.53.0