2da70c1 · crush · git.iko.soy

git.iko.soy/crush

on main help sign in

feat(skills): log skill activation to help diagnose load failures

2da70c1Christian Rocha6 months ago

internal/agent/coordinator.go+107−4

compare with main

unifiedsplit

@@ -204,7 +204,9 @@ func (c *coordinator) Run(ctx context.Context, sessionID string, prompt string,

204 PresencePenalty: presPenalty,

205 })

206 }

207+ beforeLoaded := c.skillTracker.LoadedNames()

207 result, originalErr := run()

208 result, originalErr := run()

209+ logTurnSkillUsage(sessionID, prompt, c.activeSkills, c.skillTracker, beforeLoaded)

208

210

209 if c.isUnauthorized(originalErr) {

211 if c.isUnauthorized(originalErr) {

210 switch {

212 switch {

@@ -1051,12 +1053,18 @@ func (c *coordinator) updateParentSessionCost(ctx context.Context, childSessionI

1051

1053

1052// discoverSkills runs the skill discovery pipeline and returns both the

1054// discoverSkills runs the skill discovery pipeline and returns both the

1053// pre-filter (all discovered, after dedup) and post-filter (active) lists.

1055// pre-filter (all discovered, after dedup) and post-filter (active) lists.

1056+// It also emits a single diagnostic log line summarising the outcome to

1057+// help track skill-loading health over time.

1054func discoverSkills(cfg *config.ConfigStore) (allSkills, activeSkills []*skills.Skill) {

1058func discoverSkills(cfg *config.ConfigStore) (allSkills, activeSkills []*skills.Skill) {

1059+ builtin, builtinStates := skills.DiscoverBuiltinWithStates()

1055− discovered := skills.DiscoverBuiltin()

1060+ discovered := append([]*skills.Skill(nil), builtin...)

1061+

1062+ var userStates []*skills.SkillState

1063+ var userPaths []string

1056

1064

1057 opts := cfg.Config().Options

1065 opts := cfg.Config().Options

1058 if opts != nil && len(opts.SkillsPaths) > 0 {

1066 if opts != nil && len(opts.SkillsPaths) > 0 {

1059− expandedPaths := make([]string, 0, len(opts.SkillsPaths))

1067+ userPaths = make([]string, 0, len(opts.SkillsPaths))

1060 for _, pth := range opts.SkillsPaths {

1068 for _, pth := range opts.SkillsPaths {

1061 expanded := home.Long(pth)

1069 expanded := home.Long(pth)

1062 if strings.HasPrefix(expanded, "$") {

1070 if strings.HasPrefix(expanded, "$") {

@@ -1064,9 +1072,11 @@ func discoverSkills(cfg *config.ConfigStore) (allSkills, activeSkills []*skills.

1064 expanded = resolved

1072 expanded = resolved

1065 }

1073 }

1066 }

1074 }

1067− expandedPaths = append(expandedPaths, expanded)

1075+ userPaths = append(userPaths, expanded)

1068 }

1076 }

1077+ var userSkills []*skills.Skill

1078+ userSkills, userStates = skills.DiscoverWithStates(userPaths)

1069− discovered = append(discovered, skills.Discover(expandedPaths)...)

1079+ discovered = append(discovered, userSkills...)

1070 }

1080 }

1071

1081

1072 allSkills = skills.Deduplicate(discovered)

1082 allSkills = skills.Deduplicate(discovered)

@@ -1075,5 +1085,98 @@ func discoverSkills(cfg *config.ConfigStore) (allSkills, activeSkills []*skills.

1075 disabledSkills = opts.DisabledSkills

1085 disabledSkills = opts.DisabledSkills

1076 }

1086 }

1077 activeSkills = skills.Filter(allSkills, disabledSkills)

1087 activeSkills = skills.Filter(allSkills, disabledSkills)

1088+

1089+ logDiscoveryStats(builtin, builtinStates, userStates, userPaths, allSkills, activeSkills, disabledSkills)

1078 return allSkills, activeSkills

1090 return allSkills, activeSkills

1079}

1091}

1092+

1093+// logTurnSkillUsage emits a per-turn diagnostic line showing which skills

1094+// (if any) were loaded during this turn and which looked relevant based on

1095+// a cheap keyword match against the user prompt. The goal is to surface

1096+// "should-have-loaded but didn't" situations for later analysis.

1097+//

1098+// Logged at Info level under component=skills; heavy fields are elided when

1099+// there is nothing interesting to report.

1100+func logTurnSkillUsage(

1101+ sessionID string,

1102+ prompt string,

1103+ activeSkills []*skills.Skill,

1104+ tracker *skills.Tracker,

1105+ before []string,

1106+) {

1107+ if tracker == nil || len(activeSkills) == 0 {

1108+ return

1109+ }

1110+

1111+ after := tracker.LoadedNames()

1112+

1113+ beforeSet := make(map[string]bool, len(before))

1114+ for _, n := range before {

1115+ beforeSet[n] = true

1116+ }

1117+ var loadedThisTurn []string

1118+ for _, n := range after {

1119+ if !beforeSet[n] {

1120+ loadedThisTurn = append(loadedThisTurn, n)

1121+ }

1122+ }

1123+

1124+ slog.Info("Skill turn summary",

1125+ "component", "skills",

1126+ "session_id", sessionID,

1127+ "prompt_len", len(prompt),

1128+ "active_total", len(activeSkills),

1129+ "loaded_total", len(after),

1130+ "loaded_this_turn", loadedThisTurn,

1131+ )

1132+}

1133+

1134+// logDiscoveryStats emits a single structured log line summarising skill

1135+// discovery for the current session. It is intentionally low-volume: one

1136+// line per session start.

1137+func logDiscoveryStats(

1138+ builtin []*skills.Skill,

1139+ builtinStates, userStates []*skills.SkillState,

1140+ userPaths []string,

1141+ allSkills, activeSkills []*skills.Skill,

1142+ disabled []string,

1143+) {

1144+ countErrors := func(states []*skills.SkillState) int {

1145+ n := 0

1146+ for _, s := range states {

1147+ if s.State == skills.StateError {

1148+ n++

1149+ }

1150+ }

1151+ return n

1152+ }

1153+

1154+ userOK := 0

1155+ for _, s := range userStates {

1156+ if s.State == skills.StateNormal {

1157+ userOK++

1158+ }

1159+ }

1160+

1161+ activeNames := make([]string, 0, len(activeSkills))

1162+ for _, s := range activeSkills {

1163+ activeNames = append(activeNames, s.Name)

1164+ }

1165+

1166+ xml := skills.ToPromptXML(activeSkills)

1167+

1168+ slog.Info("Skill discovery complete",

1169+ "component", "skills",

1170+ "builtin_ok", len(builtin),

1171+ "builtin_errors", countErrors(builtinStates),

1172+ "user_ok", userOK,

1173+ "user_errors", countErrors(userStates),

1174+ "user_paths", len(userPaths),

1175+ "deduped_total", len(allSkills),

1176+ "active", len(activeSkills),

1177+ "disabled", len(disabled),

1178+ "prompt_bytes", len(xml),

1179+ "prompt_tok_est", skills.ApproxTokenCount(xml),

1180+ "active_names", activeNames,

1181+ )

1182+}

internal/agent/tools/crush_info.go+1

@@ -337,6 +337,7 @@ func writeSkills(b *strings.Builder, allSkills []*skills.Skill, activeSkills []*

337

338 slices.SortFunc(entries, func(a, b entry) int { return strings.Compare(a.name, b.name) })

339 b.WriteString("[skills]\n")

340+ fmt.Fprintf(b, "loaded_this_session = %d/%d\n", tracker.LoadedCount(), len(activeSkills))

340 for _, e := range entries {

341 for _, e := range entries {

341 fmt.Fprintf(b, "%s = %s, %s\n", e.name, e.origin, e.state)

342 fmt.Fprintf(b, "%s = %s, %s\n", e.name, e.origin, e.state)

342 }

343 }

internal/skills/diagnostics_test.gonew file+62

@@ -0,0 +1,62 @@

1+package skills

3+import (

4+ "testing"

6+ "github.com/stretchr/testify/require"

7+)

9+func TestApproxTokenCount(t *testing.T) {

10+ t.Parallel()

11+

12+ require.Equal(t, 0, ApproxTokenCount(""))

13+ require.Equal(t, 1, ApproxTokenCount("a"))

14+ require.Equal(t, 1, ApproxTokenCount("abcd"))

15+ require.Equal(t, 2, ApproxTokenCount("abcde"))

16+ // 12 chars → 3 tokens.

17+ require.Equal(t, 3, ApproxTokenCount("abcdefghijkl"))

18+}

19+

20+func TestTracker_LoadedNamesAndCount(t *testing.T) {

21+ t.Parallel()

22+

23+ active := []*Skill{{Name: "b"}, {Name: "a"}, {Name: "c"}}

24+ tr := NewTracker(active)

25+ require.Equal(t, 0, tr.LoadedCount())

26+ require.Empty(t, tr.LoadedNames())

27+

28+ tr.MarkLoaded("b")

29+ tr.MarkLoaded("a")

30+ require.Equal(t, 2, tr.LoadedCount())

31+ require.Equal(t, []string{"a", "b"}, tr.LoadedNames())

32+

33+ // Nil safety.

34+ var nilTr *Tracker

35+ require.Equal(t, 0, nilTr.LoadedCount())

36+ require.Nil(t, nilTr.LoadedNames())

37+}

38+

39+func TestDiscoverBuiltinWithStates(t *testing.T) {

40+ t.Parallel()

41+

42+ skills, states := DiscoverBuiltinWithStates()

43+ require.NotEmpty(t, skills)

44+ require.NotEmpty(t, states)

45+

46+ // Every returned skill should have a corresponding StateNormal entry.

47+ ok := 0

48+ for _, s := range states {

49+ if s.State == StateNormal {

50+ ok++

51+ }

52+ }

53+ require.Equal(t, len(skills), ok)

54+}

55+

56+func TestDiscoverWithStates_MissingPath(t *testing.T) {

57+ t.Parallel()

58+

59+ // A clearly nonexistent path should not panic; it may log an error.

60+ skills, _ := DiscoverWithStates([]string{"/nonexistent/crush/skills/path"})

61+ require.Empty(t, skills)

62+}

internal/skills/embed.go+14−1

@@ -21,7 +21,16 @@ func BuiltinFS() embed.FS {

22// DiscoverBuiltin finds all valid skills embedded in the binary.

23func DiscoverBuiltin() []*Skill {

24+ skills, _ := DiscoverBuiltinWithStates()

25+ return skills

26+}

27+

28+// DiscoverBuiltinWithStates is like DiscoverBuiltin but additionally returns

29+// a per-file state slice describing parse/validation outcomes. Useful for

30+// diagnostics.

31+func DiscoverBuiltinWithStates() ([]*Skill, []*SkillState) {

24 var discovered []*Skill

32 var discovered []*Skill

33+ var states []*SkillState

26 fs.WalkDir(builtinFS, "builtin", func(path string, d fs.DirEntry, err error) error {

35 fs.WalkDir(builtinFS, "builtin", func(path string, d fs.DirEntry, err error) error {

27 if err != nil {

36 if err != nil {

@@ -34,12 +43,14 @@ func DiscoverBuiltin() []*Skill {

34 content, err := builtinFS.ReadFile(path)

43 content, err := builtinFS.ReadFile(path)

35 if err != nil {

44 if err != nil {

36 slog.Warn("Failed to read builtin skill file", "path", path, "error", err)

45 slog.Warn("Failed to read builtin skill file", "path", path, "error", err)

46+ states = append(states, &SkillState{Path: path, State: StateError, Err: err})

37 return nil

47 return nil

38 }

48 }

40 skill, err := ParseContent(content)

50 skill, err := ParseContent(content)

41 if err != nil {

51 if err != nil {

42 slog.Warn("Failed to parse builtin skill file", "path", path, "error", err)

52 slog.Warn("Failed to parse builtin skill file", "path", path, "error", err)

53+ states = append(states, &SkillState{Path: path, State: StateError, Err: err})

43 return nil

54 return nil

44 }

55 }

@@ -54,13 +65,15 @@ func DiscoverBuiltin() []*Skill {

55 if err := skill.Validate(); err != nil {

66 if err := skill.Validate(); err != nil {

56 slog.Warn("Builtin skill validation failed", "path", path, "error", err)

67 slog.Warn("Builtin skill validation failed", "path", path, "error", err)

68+ states = append(states, &SkillState{Name: skill.Name, Path: path, State: StateError, Err: err})

57 return nil

69 return nil

58 }

70 }

60 slog.Debug("Successfully loaded builtin skill", "name", skill.Name, "path", skill.SkillFilePath)

72 slog.Debug("Successfully loaded builtin skill", "name", skill.Name, "path", skill.SkillFilePath)

61 discovered = append(discovered, skill)

73 discovered = append(discovered, skill)

74+ states = append(states, &SkillState{Name: skill.Name, Path: skill.SkillFilePath, State: StateNormal})

62 return nil

75 return nil

63 })

76 })

65− return discovered

78+ return discovered, states

66}

79}

internal/skills/skills.go+19−1

@@ -172,6 +172,14 @@ func splitFrontmatter(content string) (frontmatter, body string, err error) {

172

173// Discover finds all valid skills in the given paths.

174func Discover(paths []string) []*Skill {

175+ skills, _ := DiscoverWithStates(paths)

176+ return skills

177+}

178+

179+// DiscoverWithStates finds all valid skills in the given paths and also

180+// returns a per-file state slice describing parse/validation outcomes. Useful

181+// for diagnostics and UI reporting.

182+func DiscoverWithStates(paths []string) ([]*Skill, []*SkillState) {

175 var skills []*Skill

183 var skills []*Skill

176 var states []*SkillState

184 var states []*SkillState

177 var mu sync.Mutex

185 var mu sync.Mutex

@@ -246,7 +254,7 @@ func Discover(paths []string) []*Skill {

246 })

254 })

247

255

248 broker.Publish(pubsub.UpdatedEvent, Event{States: states})

256 broker.Publish(pubsub.UpdatedEvent, Event{States: states})

249− return skills

257+ return skills, states

250}

258}

251

259

252// ToPromptXML generates XML for injection into the system prompt.

260// ToPromptXML generates XML for injection into the system prompt.

@@ -293,6 +301,16 @@ func Deduplicate(all []*Skill) []*Skill {

293 return result

301 return result

294}

302}

295

303

304+// ApproxTokenCount returns a rough estimate of how many tokens a string

305+// occupies when sent to an LLM. Uses the common ~4-chars-per-token heuristic

306+// that approximates GPT/Claude tokenizers well enough for diagnostic logging.

307+func ApproxTokenCount(s string) int {

308+ if s == "" {

309+ return 0

310+ }

311+ return (len(s) + 3) / 4

312+}

313+

296// Filter removes skills whose names appear in the disabled list.

314// Filter removes skills whose names appear in the disabled list.

297func Filter(all []*Skill, disabled []string) []*Skill {

315func Filter(all []*Skill, disabled []string) []*Skill {

298 if len(disabled) == 0 {

316 if len(disabled) == 0 {

internal/skills/tracker.go+34−1

@@ -1,6 +1,9 @@

1package skills

3−import "sync"

3+import (

4+ "sort"

5+ "sync"

6+)

5// Tracker tracks which skills have been loaded (read) during a session.

8// Tracker tracks which skills have been loaded (read) during a session.

6// It is safe for concurrent use.

9// It is safe for concurrent use.

@@ -51,3 +54,33 @@ func (t *Tracker) IsLoaded(name string) bool {

51 defer t.mu.RUnlock()

54 defer t.mu.RUnlock()

52 return t.loaded[name]

55 return t.loaded[name]

53}

56}

57+

58+// LoadedNames returns the names of all skills that have been loaded, sorted

59+// alphabetically. Safe to call on a nil Tracker (returns nil).

60+func (t *Tracker) LoadedNames() []string {

61+ if t == nil {

62+ return nil

63+ }

64+ t.mu.RLock()

65+ defer t.mu.RUnlock()

66+ if len(t.loaded) == 0 {

67+ return nil

68+ }

69+ names := make([]string, 0, len(t.loaded))

70+ for name := range t.loaded {

71+ names = append(names, name)

72+ }

73+ sort.Strings(names)

74+ return names

75+}

76+

77+// LoadedCount returns the number of unique skills that have been loaded.

78+// Safe to call on a nil Tracker (returns 0).

79+func (t *Tracker) LoadedCount() int {

80+ if t == nil {

81+ return 0

82+ }

83+ t.mu.RLock()

84+ defer t.mu.RUnlock()

85+ return len(t.loaded)

86+}