opencode/picoclaw
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

feat(orch): add execution stats to subagent completion notifications

Browse source 
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 <noreply@anthropic.com>
This commit is contained in:
dj-oyu 2026-02-25 17:20:45 +09:00
parent f50976ca43
commit b8220102c9
9 changed files with 357 additions and 20 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

37
.claude/settings.local.json Normal file
View file

@ -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"
}
}

53
pkg/agent/loop.go
View file

@ -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 {

88
pkg/agent/loop_test.go
View file

@ -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)
}
})
}
}

20
pkg/tools/sandbox_test.go
View file

@ -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 {

17
pkg/tools/shell_test.go
View file

@ -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 {

46
pkg/tools/subagent.go
View file

@ -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, ",")
}

63
pkg/tools/subagent_tool_test.go
View file

@ -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")
}
}

8
pkg/tools/toolloop.go
View file

@ -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
}

45
pkg/tools/toolloop_reporter_test.go
View file

@ -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