X-Git-Url: http://git.giacomolli.uk/onechat/blobdiff_plain/7088b82414bdf947a6f88918c0a7b2c7fb0c53ef..d7a967f43fae27bcabc6072da3b5a2f923d47764:/subagent_run.go?ds=inline

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.