From f239720aa06db160cbf8f551872750e328b79592 Mon Sep 17 00:00:00 2001 From: dj-oyu <68707227+dj-oyu@users.noreply.github.com> Date: Wed, 25 Feb 2026 17:20:45 +0900 Subject: [PATCH] feat(orch): add execution stats to subagent completion notifications MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Track tool call count, per-tool breakdown, and duration in ToolLoopResult, propagate via bus Metadata, and format as "📋 scout-1 completed (3.2s, 5 tool calls)." Co-Authored-By: Claude Opus 4.6 --- .claude/settings.local.json | 37 ++++++++++++ pkg/agent/loop.go | 53 ++++++++++++++++- pkg/agent/loop_test.go | 88 +++++++++++++++++++++++++++++ pkg/tools/sandbox_test.go | 20 +++++-- pkg/tools/shell_test.go | 17 +++--- pkg/tools/subagent.go | 46 +++++++++++++-- pkg/tools/subagent_tool_test.go | 63 +++++++++++++++++++++ pkg/tools/toolloop.go | 8 +++ pkg/tools/toolloop_reporter_test.go | 45 +++++++++++++++ 9 files changed, 357 insertions(+), 20 deletions(-) create mode 100644 .claude/settings.local.json diff --git a/.claude/settings.local.json b/.claude/settings.local.json new file mode 100644 index 000000000..11ae361fb --- /dev/null +++ b/.claude/settings.local.json @@ -0,0 +1,37 @@ +{ + "permissions": { + "allow": [ + "Bash(grep:*)", + "Bash(find:*)", + "Bash(go build:*)", + "Bash(go test:*)", + "Bash(git add:*)", + "Bash(git commit:*)", + "Bash(git push:*)", + "Bash(gh issue view:*)", + "Bash(cd /d/vscode/ai/picoclaw && go vet ./pkg/agent/ 2>&1)", + "Bash(cd:*)", + "Bash(cp:*)", + "Bash(ls:*)", + "Bash(head:*)", + "Bash(wc:*)", + "WebFetch(domain:docs.astral.sh)", + "WebFetch(domain:github.com)", + "Bash(cd /d/vscode/ai/picoclaw && go vet ./pkg/agent/... ./pkg/channels/... ./pkg/bus/... 2>&1)", + "Bash(go list:*)", + "Bash(go mod:*)", + "Bash(go env:*)", + "Bash(cd /d/vscode/ai/picoclaw && go vet ./pkg/miniapp/... ./pkg/logger/... 2>&1)", + "Bash(cd /d/vscode/ai/picoclaw && go vet ./pkg/logger/... ./pkg/miniapp/... 2>&1)", + "Bash(cd /d/vscode/ai/picoclaw && go vet ./pkg/agent/... 2>&1)", + "WebSearch", + "Bash(gh api:*)", + "Bash(gh run:*)", + "Bash(gh pr:*)", + "Bash(gofmt:*)" + ] + }, + "remote": { + "defaultEnvironmentId": "env_011CUpDfW35pH2YVfqef4sHE" + } +} diff --git a/pkg/agent/loop.go b/pkg/agent/loop.go index f3e3777f7..d85a02ce8 100644 --- a/pkg/agent/loop.go +++ b/pkg/agent/loop.go @@ -820,10 +820,11 @@ func (al *AgentLoop) processSystemMessage(ctx context.Context, msg bus.InboundMe if idx := strings.LastIndex(label, ":"); idx >= 0 { label = label[idx+1:] } + notification := formatSubagentCompletion(label, msg.Metadata) _ = al.bus.PublishOutbound(ctx, bus.OutboundMessage{ Channel: originChannel, ChatID: originChatID, - Content: fmt.Sprintf("📋 %s completed.", label), + Content: notification, SkipPlaceholder: true, }) @@ -837,6 +838,56 @@ func (al *AgentLoop) processSystemMessage(ctx context.Context, msg bus.InboundMe return "", nil } +// formatSubagentCompletion builds the user-facing notification for a completed subagent. +// If metadata contains duration_ms and tool_calls it produces e.g.: +// +// "📋 scout-1 completed (3.2s, 5 tool calls)." +// +// Without metadata it falls back to the plain "📋 scout-1 completed." format. +func formatSubagentCompletion(label string, metadata map[string]string) string { + if len(metadata) == 0 { + return fmt.Sprintf("📋 %s completed.", label) + } + durationMs, _ := strconv.ParseInt(metadata["duration_ms"], 10, 64) + toolCalls, _ := strconv.Atoi(metadata["tool_calls"]) + + if durationMs <= 0 && toolCalls <= 0 { + return fmt.Sprintf("📋 %s completed.", label) + } + + parts := make([]string, 0, 2) + if durationMs > 0 { + parts = append(parts, formatDurationMs(durationMs)) + } + if toolCalls > 0 { + if toolCalls == 1 { + parts = append(parts, "1 tool call") + } else { + parts = append(parts, fmt.Sprintf("%d tool calls", toolCalls)) + } + } + return fmt.Sprintf("📋 %s completed (%s).", label, strings.Join(parts, ", ")) +} + +// formatDurationMs converts milliseconds to a human-readable duration string. +// Examples: 800 → "0.8s", 1200 → "1.2s", 65000 → "1m5s", 3661000 → "61m1s". +func formatDurationMs(ms int64) string { + if ms < 1000 { + return fmt.Sprintf("%dms", ms) + } + totalSec := ms / 1000 + if totalSec < 60 { + tenths := (ms % 1000) / 100 + return fmt.Sprintf("%d.%ds", totalSec, tenths) + } + min := totalSec / 60 + sec := totalSec % 60 + if sec == 0 { + return fmt.Sprintf("%dm", min) + } + return fmt.Sprintf("%dm%ds", min, sec) +} + // acquireSessionLock gets or creates a per-session semaphore and acquires it. // Returns false if the context is canceled before the lock is acquired. func (al *AgentLoop) acquireSessionLock(ctx context.Context, sessionKey string) bool { diff --git a/pkg/agent/loop_test.go b/pkg/agent/loop_test.go index b1765f7c4..e7a9e2be9 100644 --- a/pkg/agent/loop_test.go +++ b/pkg/agent/loop_test.go @@ -2991,3 +2991,91 @@ func TestHandleReasoning(t *testing.T) { } }) } + +func TestFormatDurationMs(t *testing.T) { + tests := []struct { + ms int64 + want string + }{ + {0, "0ms"}, + {500, "500ms"}, + {999, "999ms"}, + {1000, "1.0s"}, + {1200, "1.2s"}, + {3500, "3.5s"}, + {59900, "59.9s"}, + {60000, "1m"}, + {61000, "1m1s"}, + {65000, "1m5s"}, + {120000, "2m"}, + {3661000, "61m1s"}, + } + for _, tt := range tests { + t.Run(fmt.Sprintf("%dms", tt.ms), func(t *testing.T) { + got := formatDurationMs(tt.ms) + if got != tt.want { + t.Errorf("formatDurationMs(%d) = %q, want %q", tt.ms, got, tt.want) + } + }) + } +} + +func TestFormatSubagentCompletion(t *testing.T) { + tests := []struct { + name string + label string + metadata map[string]string + want string + }{ + { + "no metadata", + "scout-1", + nil, + "📋 scout-1 completed.", + }, + { + "empty metadata", + "scout-1", + map[string]string{}, + "📋 scout-1 completed.", + }, + { + "duration and tool calls", + "scout-1", + map[string]string{"duration_ms": "3200", "tool_calls": "5"}, + "📋 scout-1 completed (3.2s, 5 tool calls).", + }, + { + "single tool call", + "coder-1", + map[string]string{"duration_ms": "1200", "tool_calls": "1"}, + "📋 coder-1 completed (1.2s, 1 tool call).", + }, + { + "duration only", + "scout-2", + map[string]string{"duration_ms": "65000", "tool_calls": "0"}, + "📋 scout-2 completed (1m5s).", + }, + { + "tool calls only", + "scout-3", + map[string]string{"duration_ms": "0", "tool_calls": "10"}, + "📋 scout-3 completed (10 tool calls).", + }, + { + "zero everything", + "scout-4", + map[string]string{"duration_ms": "0", "tool_calls": "0"}, + "📋 scout-4 completed.", + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + got := formatSubagentCompletion(tt.label, tt.metadata) + if got != tt.want { + t.Errorf("formatSubagentCompletion(%q, %v) = %q, want %q", tt.label, tt.metadata, got, tt.want) + } + }) + } +} diff --git a/pkg/tools/sandbox_test.go b/pkg/tools/sandbox_test.go index 3d4b37788..84243aeb9 100644 --- a/pkg/tools/sandbox_test.go +++ b/pkg/tools/sandbox_test.go @@ -173,7 +173,10 @@ func TestPresetAllowRules_Coder(t *testing.T) { t.Fatalf("coder rules missing or empty") } - exec := NewExecTool(t.TempDir(), true) + exec, err := NewExecTool(t.TempDir(), true) + if err != nil { + t.Fatalf("NewExecTool: %v", err) + } exec.SetAllowRules(rules) tests := []struct { @@ -224,7 +227,10 @@ func TestPresetAllowRules_Analyst(t *testing.T) { t.Fatalf("analyst rules missing or empty") } - exec := NewExecTool(t.TempDir(), true) + exec, err := NewExecTool(t.TempDir(), true) + if err != nil { + t.Fatalf("NewExecTool: %v", err) + } exec.SetAllowRules(rules) tests := []struct { @@ -264,7 +270,10 @@ func TestPresetAllowRules_Worker(t *testing.T) { t.Fatalf("worker rules missing or empty") } - exec := NewExecTool(t.TempDir(), true) + exec, err := NewExecTool(t.TempDir(), true) + if err != nil { + t.Fatalf("NewExecTool: %v", err) + } exec.SetAllowRules(rules) tests := []struct { @@ -306,7 +315,10 @@ func TestPresetAllowRules_Coordinator(t *testing.T) { t.Fatalf("coordinator rules missing or empty") } - exec := NewExecTool(t.TempDir(), true) + exec, err := NewExecTool(t.TempDir(), true) + if err != nil { + t.Fatalf("NewExecTool: %v", err) + } exec.SetAllowRules(rules) tests := []struct { diff --git a/pkg/tools/shell_test.go b/pkg/tools/shell_test.go index 20ea7e23e..2203beffd 100644 --- a/pkg/tools/shell_test.go +++ b/pkg/tools/shell_test.go @@ -573,15 +573,12 @@ func TestGuardCommand_DenyPattern_IncludesPattern(t *testing.T) { } } -// TestGuardCommand_Allowlist_ShowsPatterns verifies that allowlist violation -// messages include all configured patterns. -func TestGuardCommand_Allowlist_ShowsPatterns(t *testing.T) { +// TestGuardCommand_Allowlist_ShowsRules verifies that allowlist violation +// messages include all configured rules. +func TestGuardCommand_Allowlist_ShowsRules(t *testing.T) { workspace := t.TempDir() tool, _ := NewExecTool(workspace, true) - err := tool.SetAllowPatterns([]string{`^go\b`, `^git\b`}) - if err != nil { - t.Fatalf("SetAllowPatterns failed: %v", err) - } + tool.SetAllowRules([]string{"go test", "git"}) result := tool.guardCommand("curl http://example.com", workspace) if result == "" { @@ -590,8 +587,8 @@ func TestGuardCommand_Allowlist_ShowsPatterns(t *testing.T) { if !strings.Contains(result, "not in allowlist") { t.Errorf("expected 'not in allowlist' in message, got: %s", result) } - if !strings.Contains(result, `^go\b`) || !strings.Contains(result, `^git\b`) { - t.Errorf("expected allowlist patterns in message, got: %s", result) + if !strings.Contains(result, "go test") || !strings.Contains(result, "git") { + t.Errorf("expected allowlist rules in message, got: %s", result) } } @@ -1054,7 +1051,7 @@ func TestCheckCurlLocalNet(t *testing.T) { // TestExecTool_LocalNetOnly verifies curl/wget blocking via SetLocalNetOnly. func TestExecTool_LocalNetOnly(t *testing.T) { - tool := NewExecTool("", false) + tool, _ := NewExecTool("", false) tool.SetLocalNetOnly(true) tests := []struct { diff --git a/pkg/tools/subagent.go b/pkg/tools/subagent.go index d37ac60f5..073b5274a 100644 --- a/pkg/tools/subagent.go +++ b/pkg/tools/subagent.go @@ -3,6 +3,9 @@ package tools import ( "context" "fmt" + "sort" + "strconv" + "strings" "sync" "time" @@ -21,6 +24,10 @@ type SubagentTask struct { Status string Result string Created int64 + CompletedAt int64 `json:"-"` + Iterations int `json:"-"` + ToolCalls int `json:"-"` + ToolStats map[string]int `json:"-"` } type SubagentManager struct { @@ -241,14 +248,19 @@ After completing, provide a clear summary of what was done and how it was verifi } else { task.Status = "completed" task.Result = loopResult.Content + task.CompletedAt = time.Now().UnixMilli() + task.Iterations = loopResult.Iterations + task.ToolCalls = loopResult.ToolCalls + task.ToolStats = loopResult.ToolStats // Notify conductor of the result sm.reporter.ReportConversation(task.ID, "conductor", loopResult.Content) sm.reporter.ReportGC(task.ID, "completed") result = &ToolResult{ ForLLM: fmt.Sprintf( - "Subagent '%s' completed (iterations: %d): %s", + "Subagent '%s' completed (iterations: %d, tool calls: %d): %s", task.Label, loopResult.Iterations, + loopResult.ToolCalls, loopResult.Content, ), ForUser: loopResult.Content, @@ -261,14 +273,23 @@ After completing, provide a clear summary of what was done and how it was verifi // Send announce message back to main agent if sm.bus != nil { announceContent := fmt.Sprintf("Task '%s' completed.\n\nResult:\n%s", task.Label, task.Result) + metadata := map[string]string{ + "duration_ms": strconv.FormatInt(task.CompletedAt-task.Created, 10), + "iterations": strconv.Itoa(task.Iterations), + "tool_calls": strconv.Itoa(task.ToolCalls), + } + if len(task.ToolStats) > 0 { + metadata["tool_stats"] = formatToolStats(task.ToolStats) + } pubCtx, pubCancel := context.WithTimeout(context.Background(), 5*time.Second) defer pubCancel() sm.bus.PublishInbound(pubCtx, bus.InboundMessage{ Channel: "system", SenderID: fmt.Sprintf("subagent:%s", task.ID), // Format: "original_channel:original_chat_id" for routing back - ChatID: fmt.Sprintf("%s:%s", task.OriginChannel, task.OriginChatID), - Content: announceContent, + ChatID: fmt.Sprintf("%s:%s", task.OriginChannel, task.OriginChatID), + Content: announceContent, + Metadata: metadata, }) } } @@ -481,8 +502,8 @@ func (t *SubagentTool) Execute(ctx context.Context, args map[string]any) *ToolRe if labelStr == "" { labelStr = "(unnamed)" } - llmContent := fmt.Sprintf("Subagent task completed:\nLabel: %s\nIterations: %d\nResult: %s", - labelStr, loopResult.Iterations, loopResult.Content) + llmContent := fmt.Sprintf("Subagent task completed:\nLabel: %s\nIterations: %d\nTool calls: %d\nResult: %s", + labelStr, loopResult.Iterations, loopResult.ToolCalls, loopResult.Content) return &ToolResult{ ForLLM: llmContent, @@ -492,3 +513,18 @@ func (t *SubagentTool) Execute(ctx context.Context, args map[string]any) *ToolRe Async: false, } } + +// formatToolStats formats a tool stats map as a compact string: "exec:3,read_file:5". +// Keys are sorted alphabetically for deterministic output. +func formatToolStats(stats map[string]int) string { + keys := make([]string, 0, len(stats)) + for k := range stats { + keys = append(keys, k) + } + sort.Strings(keys) + parts := make([]string, 0, len(keys)) + for _, k := range keys { + parts = append(parts, k+":"+strconv.Itoa(stats[k])) + } + return strings.Join(parts, ",") +} diff --git a/pkg/tools/subagent_tool_test.go b/pkg/tools/subagent_tool_test.go index 43d5a8fc7..010bf13da 100644 --- a/pkg/tools/subagent_tool_test.go +++ b/pkg/tools/subagent_tool_test.go @@ -4,6 +4,7 @@ import ( "context" "strings" "testing" + "time" "github.com/sipeed/picoclaw/pkg/bus" "github.com/sipeed/picoclaw/pkg/orch" @@ -355,3 +356,65 @@ func TestSubagentTool_ForUserTruncation(t *testing.T) { t.Error("ForLLM should contain reference to original task") } } + +func TestFormatToolStats(t *testing.T) { + tests := []struct { + name string + stats map[string]int + want string + }{ + {"empty", map[string]int{}, ""}, + {"single", map[string]int{"exec": 3}, "exec:3"}, + {"multiple sorted", map[string]int{"read_file": 5, "exec": 3, "write_file": 1}, "exec:3,read_file:5,write_file:1"}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + got := formatToolStats(tt.stats) + if got != tt.want { + t.Errorf("formatToolStats(%v) = %q, want %q", tt.stats, got, tt.want) + } + }) + } +} + +// TestSubagentManager_Spawn_SetsMetadata verifies that the bus message from a +// completed spawn includes execution statistics in Metadata. +func TestSubagentManager_Spawn_SetsMetadata(t *testing.T) { + provider := &MockLLMProvider{} + msgBus := bus.NewMessageBus() + mgr := NewSubagentManager(provider, "test-model", "/tmp/test", msgBus, orch.Noop, WebSearchToolOptions{}) + + _, err := mgr.Spawn( + context.Background(), + "say hello", "meta-test", "", "cli", "direct", "", + nil, + ) + if err != nil { + t.Fatalf("Spawn() error: %v", err) + } + + // Consume the inbound message from the bus + ctx, cancel := context.WithTimeout(context.Background(), 3*time.Second) + defer cancel() + received, ok := msgBus.ConsumeInbound(ctx) + if !ok { + t.Fatal("timed out waiting for bus message") + } + + if received.Channel != "system" { + t.Fatalf("expected channel 'system', got %q", received.Channel) + } + if received.Metadata == nil { + t.Fatal("Metadata should not be nil") + } + if received.Metadata["iterations"] != "1" { + t.Errorf("iterations = %q, want %q", received.Metadata["iterations"], "1") + } + if received.Metadata["tool_calls"] != "0" { + t.Errorf("tool_calls = %q, want %q", received.Metadata["tool_calls"], "0") + } + // duration_ms should be a non-negative number + if received.Metadata["duration_ms"] == "" { + t.Error("duration_ms should be present") + } +} diff --git a/pkg/tools/toolloop.go b/pkg/tools/toolloop.go index da7e06253..6351879a0 100644 --- a/pkg/tools/toolloop.go +++ b/pkg/tools/toolloop.go @@ -36,6 +36,8 @@ type ToolLoopConfig struct { type ToolLoopResult struct { Content string Iterations int + ToolCalls int // total tool call count across all iterations + ToolStats map[string]int // tool name → call count } // RunToolLoop executes the LLM + tool call iteration loop. @@ -52,6 +54,8 @@ func RunToolLoop( } iteration := 0 + totalToolCalls := 0 + toolStats := map[string]int{} var finalContent string for iteration < config.MaxIterations { @@ -144,6 +148,8 @@ func RunToolLoop( "iteration": iteration, }) reporter.ReportStateChange(config.AgentID, orch.AgentStateToolCall, tc.Name) + totalToolCalls++ + toolStats[tc.Name]++ // Execute tool (no async callback for subagents - they run independently) var toolResult *ToolResult @@ -172,5 +178,7 @@ func RunToolLoop( return &ToolLoopResult{ Content: finalContent, Iterations: iteration, + ToolCalls: totalToolCalls, + ToolStats: toolStats, }, nil } diff --git a/pkg/tools/toolloop_reporter_test.go b/pkg/tools/toolloop_reporter_test.go index 3402bc13a..e8b3da971 100644 --- a/pkg/tools/toolloop_reporter_test.go +++ b/pkg/tools/toolloop_reporter_test.go @@ -163,6 +163,51 @@ func TestToolLoop_Reporter_ToolcallOrderedAfterWaiting(t *testing.T) { } } +// TestToolLoop_ToolCallStats verifies that ToolLoopResult.ToolCalls and +// ToolStats are populated correctly after a tool call iteration. +func TestToolLoop_ToolCallStats(t *testing.T) { + reg := NewToolRegistry() + reg.Register(&echoTool{}) + + result, err := RunToolLoop(context.Background(), ToolLoopConfig{ + Provider: &sequenceMockProvider{}, + Model: "test", + Tools: reg, + MaxIterations: 5, + }, []providers.Message{{Role: "user", Content: "do it"}}, "cli", "direct") + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + if result.ToolCalls != 1 { + t.Errorf("ToolCalls = %d, want 1", result.ToolCalls) + } + if result.ToolStats["echo_tool"] != 1 { + t.Errorf("ToolStats[echo_tool] = %d, want 1", result.ToolStats["echo_tool"]) + } + if result.Iterations != 2 { + t.Errorf("Iterations = %d, want 2", result.Iterations) + } +} + +// TestToolLoop_NoToolCalls_ZeroStats verifies that a direct answer (no tool +// calls) produces zero ToolCalls and an empty ToolStats map. +func TestToolLoop_NoToolCalls_ZeroStats(t *testing.T) { + result, err := RunToolLoop(context.Background(), ToolLoopConfig{ + Provider: &MockLLMProvider{}, + Model: "test", + MaxIterations: 1, + }, []providers.Message{{Role: "user", Content: "hi"}}, "cli", "direct") + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + if result.ToolCalls != 0 { + t.Errorf("ToolCalls = %d, want 0", result.ToolCalls) + } + if len(result.ToolStats) != 0 { + t.Errorf("ToolStats = %v, want empty", result.ToolStats) + } +} + // TestToolLoop_Reporter_NoopImplementsInterface is a compile-time check that // orch.Noop satisfies the orch.AgentReporter interface accepted by // ToolLoopConfig.Reporter. If Noop ever stops implementing the interface the