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.

diff --git a/subagent_run.go b/subagent_run.go
index ca4ebd4247fd3038cd8a9902ad2ea77482d3872c..67cf79d7ac14949738e2e167ee8269d45b9409a2 100644 (file)
--- a/subagent_run.go
+++ b/subagent_run.go
@@ -12,6 +12,7 @@ import (
        "slices"
        "strings"
        "sync"
        "slices"
        "strings"
        "sync"

+       "time"

 )
 
 const (
 )
 
 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)
 }
 
        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))
 
 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()
 
        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,
        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)
 }
 
        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()
 // 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
        }
 
                status = subagentStopped
        }
 

+       length := durationText(r.subagents.clock().Sub(run.started))

        switch status {
        case subagentStopped:
        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:
        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:
        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)
        }
 
        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,
 
 // 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
 // and the stop.
 type SubagentRun struct {
        subagent *Subagent


@@ -529,6 +533,7 @@ type SubagentRun struct {
        cancel   context.CancelFunc
        pending  []Message
        stopped  bool
        cancel   context.CancelFunc
        pending  []Message
        stopped  bool

+       started  time.Time

 }
 
 // SubagentWorkFile is the content of work.json.
 }
 
 // SubagentWorkFile is the content of work.json.

diff --git a/subagent_run_test.go b/subagent_run_test.go
index 125ca332cf12c94c3df00c4e994858735e6cc525..a39d81c7b7fc990cf644454c267e35aa823262d4 100644 (file)
--- 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"))
                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() {
 
        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)
                "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) {
 }
 
 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)
                "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)
 
        log, err := subagent.Show()
        require.NoError(t, err)