From 2da70c19712618b4e0ecd15b99df3a23a7acad8a Mon Sep 17 00:00:00 2001 From: Christian Rocha Date: Sun, 19 Apr 2026 14:01:36 -0400 Subject: [PATCH] feat(skills): log skill activation to help diagnose load failures --- internal/agent/coordinator.go | 111 +++++++++++++++++++++++++++- internal/agent/tools/crush_info.go | 1 + internal/skills/diagnostics_test.go | 62 ++++++++++++++++ internal/skills/embed.go | 15 +++- internal/skills/skills.go | 20 ++++- internal/skills/tracker.go | 35 ++++++++- 6 files changed, 237 insertions(+), 7 deletions(-) create mode 100644 internal/skills/diagnostics_test.go diff --git a/internal/agent/coordinator.go b/internal/agent/coordinator.go index 72723a2ff636ba8149138fa91f1310b669dd1023..53f0718b040b4e84ec3b656cc6714b45a1a2f8df 100644 --- a/internal/agent/coordinator.go +++ b/internal/agent/coordinator.go @@ -204,7 +204,9 @@ func (c *coordinator) Run(ctx context.Context, sessionID string, prompt string, PresencePenalty: presPenalty, }) } + beforeLoaded := c.skillTracker.LoadedNames() result, originalErr := run() + logTurnSkillUsage(sessionID, prompt, c.activeSkills, c.skillTracker, beforeLoaded) if c.isUnauthorized(originalErr) { switch { @@ -1051,12 +1053,18 @@ func (c *coordinator) updateParentSessionCost(ctx context.Context, childSessionI // discoverSkills runs the skill discovery pipeline and returns both the // pre-filter (all discovered, after dedup) and post-filter (active) lists. +// It also emits a single diagnostic log line summarising the outcome to +// help track skill-loading health over time. func discoverSkills(cfg *config.ConfigStore) (allSkills, activeSkills []*skills.Skill) { - discovered := skills.DiscoverBuiltin() + builtin, builtinStates := skills.DiscoverBuiltinWithStates() + discovered := append([]*skills.Skill(nil), builtin...) + + var userStates []*skills.SkillState + var userPaths []string opts := cfg.Config().Options if opts != nil && len(opts.SkillsPaths) > 0 { - expandedPaths := make([]string, 0, len(opts.SkillsPaths)) + userPaths = make([]string, 0, len(opts.SkillsPaths)) for _, pth := range opts.SkillsPaths { expanded := home.Long(pth) if strings.HasPrefix(expanded, "$") { @@ -1064,9 +1072,11 @@ func discoverSkills(cfg *config.ConfigStore) (allSkills, activeSkills []*skills. expanded = resolved } } - expandedPaths = append(expandedPaths, expanded) + userPaths = append(userPaths, expanded) } - discovered = append(discovered, skills.Discover(expandedPaths)...) + var userSkills []*skills.Skill + userSkills, userStates = skills.DiscoverWithStates(userPaths) + discovered = append(discovered, userSkills...) } allSkills = skills.Deduplicate(discovered) @@ -1075,5 +1085,98 @@ func discoverSkills(cfg *config.ConfigStore) (allSkills, activeSkills []*skills. disabledSkills = opts.DisabledSkills } activeSkills = skills.Filter(allSkills, disabledSkills) + + logDiscoveryStats(builtin, builtinStates, userStates, userPaths, allSkills, activeSkills, disabledSkills) return allSkills, activeSkills } + +// logTurnSkillUsage emits a per-turn diagnostic line showing which skills +// (if any) were loaded during this turn and which looked relevant based on +// a cheap keyword match against the user prompt. The goal is to surface +// "should-have-loaded but didn't" situations for later analysis. +// +// Logged at Info level under component=skills; heavy fields are elided when +// there is nothing interesting to report. +func logTurnSkillUsage( + sessionID string, + prompt string, + activeSkills []*skills.Skill, + tracker *skills.Tracker, + before []string, +) { + if tracker == nil || len(activeSkills) == 0 { + return + } + + after := tracker.LoadedNames() + + beforeSet := make(map[string]bool, len(before)) + for _, n := range before { + beforeSet[n] = true + } + var loadedThisTurn []string + for _, n := range after { + if !beforeSet[n] { + loadedThisTurn = append(loadedThisTurn, n) + } + } + + slog.Info("Skill turn summary", + "component", "skills", + "session_id", sessionID, + "prompt_len", len(prompt), + "active_total", len(activeSkills), + "loaded_total", len(after), + "loaded_this_turn", loadedThisTurn, + ) +} + +// logDiscoveryStats emits a single structured log line summarising skill +// discovery for the current session. It is intentionally low-volume: one +// line per session start. +func logDiscoveryStats( + builtin []*skills.Skill, + builtinStates, userStates []*skills.SkillState, + userPaths []string, + allSkills, activeSkills []*skills.Skill, + disabled []string, +) { + countErrors := func(states []*skills.SkillState) int { + n := 0 + for _, s := range states { + if s.State == skills.StateError { + n++ + } + } + return n + } + + userOK := 0 + for _, s := range userStates { + if s.State == skills.StateNormal { + userOK++ + } + } + + activeNames := make([]string, 0, len(activeSkills)) + for _, s := range activeSkills { + activeNames = append(activeNames, s.Name) + } + + xml := skills.ToPromptXML(activeSkills) + + slog.Info("Skill discovery complete", + "component", "skills", + "builtin_ok", len(builtin), + "builtin_errors", countErrors(builtinStates), + "user_ok", userOK, + "user_errors", countErrors(userStates), + "user_paths", len(userPaths), + "deduped_total", len(allSkills), + "active", len(activeSkills), + "disabled", len(disabled), + "prompt_bytes", len(xml), + "prompt_tok_est", skills.ApproxTokenCount(xml), + "active_names", activeNames, + ) +} diff --git a/internal/agent/tools/crush_info.go b/internal/agent/tools/crush_info.go index 1b7d2d41f222676eeab24c9fc7b657031c90410f..d1529d837f840e574c0347d0487f39ae0d3fce13 100644 --- a/internal/agent/tools/crush_info.go +++ b/internal/agent/tools/crush_info.go @@ -337,6 +337,7 @@ func writeSkills(b *strings.Builder, allSkills []*skills.Skill, activeSkills []* slices.SortFunc(entries, func(a, b entry) int { return strings.Compare(a.name, b.name) }) b.WriteString("[skills]\n") + fmt.Fprintf(b, "loaded_this_session = %d/%d\n", tracker.LoadedCount(), len(activeSkills)) for _, e := range entries { fmt.Fprintf(b, "%s = %s, %s\n", e.name, e.origin, e.state) } diff --git a/internal/skills/diagnostics_test.go b/internal/skills/diagnostics_test.go new file mode 100644 index 0000000000000000000000000000000000000000..3d5e784074112817287e8ec7b8deae64264915e2 --- /dev/null +++ b/internal/skills/diagnostics_test.go @@ -0,0 +1,62 @@ +package skills + +import ( + "testing" + + "github.com/stretchr/testify/require" +) + +func TestApproxTokenCount(t *testing.T) { + t.Parallel() + + require.Equal(t, 0, ApproxTokenCount("")) + require.Equal(t, 1, ApproxTokenCount("a")) + require.Equal(t, 1, ApproxTokenCount("abcd")) + require.Equal(t, 2, ApproxTokenCount("abcde")) + // 12 chars → 3 tokens. + require.Equal(t, 3, ApproxTokenCount("abcdefghijkl")) +} + +func TestTracker_LoadedNamesAndCount(t *testing.T) { + t.Parallel() + + active := []*Skill{{Name: "b"}, {Name: "a"}, {Name: "c"}} + tr := NewTracker(active) + require.Equal(t, 0, tr.LoadedCount()) + require.Empty(t, tr.LoadedNames()) + + tr.MarkLoaded("b") + tr.MarkLoaded("a") + require.Equal(t, 2, tr.LoadedCount()) + require.Equal(t, []string{"a", "b"}, tr.LoadedNames()) + + // Nil safety. + var nilTr *Tracker + require.Equal(t, 0, nilTr.LoadedCount()) + require.Nil(t, nilTr.LoadedNames()) +} + +func TestDiscoverBuiltinWithStates(t *testing.T) { + t.Parallel() + + skills, states := DiscoverBuiltinWithStates() + require.NotEmpty(t, skills) + require.NotEmpty(t, states) + + // Every returned skill should have a corresponding StateNormal entry. + ok := 0 + for _, s := range states { + if s.State == StateNormal { + ok++ + } + } + require.Equal(t, len(skills), ok) +} + +func TestDiscoverWithStates_MissingPath(t *testing.T) { + t.Parallel() + + // A clearly nonexistent path should not panic; it may log an error. + skills, _ := DiscoverWithStates([]string{"/nonexistent/crush/skills/path"}) + require.Empty(t, skills) +} diff --git a/internal/skills/embed.go b/internal/skills/embed.go index fc3b41f21cc8a09287eadc6956c4557fdf475079..ae8600a9f492ee8d2c321d84d7fbbfd68423b134 100644 --- a/internal/skills/embed.go +++ b/internal/skills/embed.go @@ -21,7 +21,16 @@ func BuiltinFS() embed.FS { // DiscoverBuiltin finds all valid skills embedded in the binary. func DiscoverBuiltin() []*Skill { + skills, _ := DiscoverBuiltinWithStates() + return skills +} + +// DiscoverBuiltinWithStates is like DiscoverBuiltin but additionally returns +// a per-file state slice describing parse/validation outcomes. Useful for +// diagnostics. +func DiscoverBuiltinWithStates() ([]*Skill, []*SkillState) { var discovered []*Skill + var states []*SkillState fs.WalkDir(builtinFS, "builtin", func(path string, d fs.DirEntry, err error) error { if err != nil { @@ -34,12 +43,14 @@ func DiscoverBuiltin() []*Skill { content, err := builtinFS.ReadFile(path) if err != nil { slog.Warn("Failed to read builtin skill file", "path", path, "error", err) + states = append(states, &SkillState{Path: path, State: StateError, Err: err}) return nil } skill, err := ParseContent(content) if err != nil { slog.Warn("Failed to parse builtin skill file", "path", path, "error", err) + states = append(states, &SkillState{Path: path, State: StateError, Err: err}) return nil } @@ -54,13 +65,15 @@ func DiscoverBuiltin() []*Skill { if err := skill.Validate(); err != nil { slog.Warn("Builtin skill validation failed", "path", path, "error", err) + states = append(states, &SkillState{Name: skill.Name, Path: path, State: StateError, Err: err}) return nil } slog.Debug("Successfully loaded builtin skill", "name", skill.Name, "path", skill.SkillFilePath) discovered = append(discovered, skill) + states = append(states, &SkillState{Name: skill.Name, Path: skill.SkillFilePath, State: StateNormal}) return nil }) - return discovered + return discovered, states } diff --git a/internal/skills/skills.go b/internal/skills/skills.go index 8dad22ec4982ed7369cbe70f7dd2b9a3f1f678b4..cb2500fd3332cbbe269e6232c899a527ed18e9d4 100644 --- a/internal/skills/skills.go +++ b/internal/skills/skills.go @@ -172,6 +172,14 @@ func splitFrontmatter(content string) (frontmatter, body string, err error) { // Discover finds all valid skills in the given paths. func Discover(paths []string) []*Skill { + skills, _ := DiscoverWithStates(paths) + return skills +} + +// DiscoverWithStates finds all valid skills in the given paths and also +// returns a per-file state slice describing parse/validation outcomes. Useful +// for diagnostics and UI reporting. +func DiscoverWithStates(paths []string) ([]*Skill, []*SkillState) { var skills []*Skill var states []*SkillState var mu sync.Mutex @@ -246,7 +254,7 @@ func Discover(paths []string) []*Skill { }) broker.Publish(pubsub.UpdatedEvent, Event{States: states}) - return skills + return skills, states } // ToPromptXML generates XML for injection into the system prompt. @@ -293,6 +301,16 @@ func Deduplicate(all []*Skill) []*Skill { return result } +// ApproxTokenCount returns a rough estimate of how many tokens a string +// occupies when sent to an LLM. Uses the common ~4-chars-per-token heuristic +// that approximates GPT/Claude tokenizers well enough for diagnostic logging. +func ApproxTokenCount(s string) int { + if s == "" { + return 0 + } + return (len(s) + 3) / 4 +} + // Filter removes skills whose names appear in the disabled list. func Filter(all []*Skill, disabled []string) []*Skill { if len(disabled) == 0 { diff --git a/internal/skills/tracker.go b/internal/skills/tracker.go index 4910d8390e6a95ebe3974d43a802e9ec6d82164e..659688d812cd3bd85c5ed1d11e6e47222741b4b1 100644 --- a/internal/skills/tracker.go +++ b/internal/skills/tracker.go @@ -1,6 +1,9 @@ package skills -import "sync" +import ( + "sort" + "sync" +) // Tracker tracks which skills have been loaded (read) during a session. // It is safe for concurrent use. @@ -51,3 +54,33 @@ func (t *Tracker) IsLoaded(name string) bool { defer t.mu.RUnlock() return t.loaded[name] } + +// LoadedNames returns the names of all skills that have been loaded, sorted +// alphabetically. Safe to call on a nil Tracker (returns nil). +func (t *Tracker) LoadedNames() []string { + if t == nil { + return nil + } + t.mu.RLock() + defer t.mu.RUnlock() + if len(t.loaded) == 0 { + return nil + } + names := make([]string, 0, len(t.loaded)) + for name := range t.loaded { + names = append(names, name) + } + sort.Strings(names) + return names +} + +// LoadedCount returns the number of unique skills that have been loaded. +// Safe to call on a nil Tracker (returns 0). +func (t *Tracker) LoadedCount() int { + if t == nil { + return 0 + } + t.mu.RLock() + defer t.mu.RUnlock() + return len(t.loaded) +}