From 6c5d2710ec12884e63a7bda20d6efbad54309cd6 Mon Sep 17 00:00:00 2001 From: "github-actions[bot]" <41898282+github-actions[bot]@users.noreply.github.com> Date: Mon, 4 May 2026 04:44:13 +0000 Subject: [PATCH] log: add debug logging to model, heredoc, sub-agent, and experiment packages Co-Authored-By: Claude Sonnet 4.6 --- pkg/cli/experiments_analyze_statistics.go | 8 ++++++++ pkg/parser/sub_agent_extractor.go | 11 +++++++++++ pkg/workflow/heredoc_validation.go | 10 ++++++++++ pkg/workflow/model_aliases.go | 18 +++++++++++++++++- pkg/workflow/model_identifier.go | 12 ++++++++++++ 5 files changed, 58 insertions(+), 1 deletion(-) diff --git a/pkg/cli/experiments_analyze_statistics.go b/pkg/cli/experiments_analyze_statistics.go index 021be38fa0e..e23fd600dd3 100644 --- a/pkg/cli/experiments_analyze_statistics.go +++ b/pkg/cli/experiments_analyze_statistics.go @@ -8,9 +8,12 @@ import ( "strings" "github.com/github/gh-aw/pkg/console" + "github.com/github/gh-aw/pkg/logger" "github.com/github/gh-aw/pkg/workflow" ) +var experimentsStatsLog = logger.New("cli:experiments_statistics") + // defaultMinSamples is the minimum samples per variant before analysis is reliable (§11.4 / R-STAT-007). const defaultMinSamples = 20 @@ -95,6 +98,7 @@ type GuardrailStatus struct { // computeExperimentAnalysis computes the statistical analysis for a single named experiment. // cfg may be nil when no workflow frontmatter is available, in which case defaults are used. func computeExperimentAnalysis(exp ExperimentVariantStats, cfg *workflow.ExperimentConfig) ExperimentAnalysis { + experimentsStatsLog.Printf("Computing analysis for experiment %q: %d variant(s), %d total runs", exp.Name, len(exp.Variants), exp.Total) a := ExperimentAnalysis{ ExperimentName: exp.Name, TotalRuns: exp.Total, @@ -103,6 +107,7 @@ func computeExperimentAnalysis(exp ExperimentVariantStats, cfg *workflow.Experim // Degenerate: fewer than 2 variants cannot be meaningfully analysed. if len(exp.Variants) < 2 { + experimentsStatsLog.Printf("Experiment %q has fewer than 2 variants; skipping analysis", exp.Name) a.IsBalanced = true a.Recommendation = "EXTEND" a.Rationale = "experiment has fewer than 2 variants; cannot perform statistical analysis" @@ -169,6 +174,7 @@ func computeExperimentAnalysis(exp ExperimentVariantStats, cfg *workflow.Experim a.DegreesOfFreedom = df a.PValue = pval a.IsBalanced = pval >= balanceSignificanceThreshold + experimentsStatsLog.Printf("Chi-square balance test for %q: χ²=%.3f df=%d p=%.3f balanced=%v", exp.Name, chi2, df, pval, a.IsBalanced) } else { a.IsBalanced = true // insufficient data to assess balance } @@ -193,10 +199,12 @@ func computeExperimentAnalysis(exp ExperimentVariantStats, cfg *workflow.Experim a.Recommendation = "EXTEND" a.Rationale = fmt.Sprintf("%d of %d variant(s) below min_samples threshold (min observed: %d / %d)", belowCount, k, minObserved, a.MinSamples) + experimentsStatsLog.Printf("Experiment %q recommendation: EXTEND (%d/%d variants below min_samples=%d)", exp.Name, belowCount, k, a.MinSamples) } else { a.Recommendation = "READY_FOR_ANALYSIS" a.Rationale = fmt.Sprintf("all %d variants have reached min_samples (%d); proceed with outcome metric analysis", k, a.MinSamples) + experimentsStatsLog.Printf("Experiment %q recommendation: READY_FOR_ANALYSIS (all %d variants above min_samples=%d)", exp.Name, k, a.MinSamples) } return a diff --git a/pkg/parser/sub_agent_extractor.go b/pkg/parser/sub_agent_extractor.go index 2c518b7216c..25e2cf89c50 100644 --- a/pkg/parser/sub_agent_extractor.go +++ b/pkg/parser/sub_agent_extractor.go @@ -71,8 +71,12 @@ import ( "regexp" "sort" "strings" + + "github.com/github/gh-aw/pkg/logger" ) +var subAgentLog = logger.New("parser:sub_agent_extractor") + // validSubAgentFrontmatterFields is the set of permitted keys in a sub-agent // frontmatter block. Any key not in this set will produce a warning when // ValidateInlineSubAgentsFrontmatter is called. @@ -242,18 +246,23 @@ var h2HeadingRegex = regexp.MustCompile(`(?m)^##[ \t]`) // If no start markers are found the original markdown is returned unchanged and // agents is nil. func ExtractInlineSubAgents(markdown string) (mainMarkdown string, agents []InlineSubAgent, err error) { + subAgentLog.Printf("Extracting inline sub-agents from markdown (length: %d)", len(markdown)) // Find all start markers (returned in document order by FindAllStringSubmatchIndex). allStarts := subAgentSeparatorRegex.FindAllStringSubmatchIndex(markdown, -1) if len(allStarts) == 0 { // No start markers — return unchanged. + subAgentLog.Print("No inline sub-agent markers found") return markdown, nil, nil } + subAgentLog.Printf("Found %d inline sub-agent marker(s)", len(allStarts)) + // Validate that all agent names are unique. seen := make(map[string]struct{}) for _, m := range allStarts { name := markdown[m[2]:m[3]] if _, exists := seen[name]; exists { + subAgentLog.Printf("Duplicate sub-agent name: %q", name) return "", nil, fmt.Errorf("duplicate inline sub-agent name %q", name) } seen[name] = struct{}{} @@ -294,8 +303,10 @@ func ExtractInlineSubAgents(markdown string) (mainMarkdown string, agents []Inli contentEnd := nextH2After(lineEnd) content := strings.TrimSpace(markdown[lineEnd:contentEnd]) + subAgentLog.Printf("Extracted sub-agent %q (content length: %d)", name, len(content)) agents = append(agents, InlineSubAgent{Name: name, Content: content}) } + subAgentLog.Printf("Extraction complete: %d sub-agent(s), main markdown length: %d", len(agents), len(mainMarkdown)) return mainMarkdown, agents, nil } diff --git a/pkg/workflow/heredoc_validation.go b/pkg/workflow/heredoc_validation.go index d9947509023..9017b324f57 100644 --- a/pkg/workflow/heredoc_validation.go +++ b/pkg/workflow/heredoc_validation.go @@ -9,8 +9,12 @@ import ( "errors" "fmt" "strings" + + "github.com/github/gh-aw/pkg/logger" ) +var heredocLog = logger.New("workflow:heredoc_validation") + // ValidateHeredocContent checks that content does not contain the heredoc delimiter // anywhere (substring match). The check is intentionally stricter than what shell // heredocs require (delimiter on its own line) — rejecting any occurrence eliminates @@ -24,6 +28,7 @@ import ( // delimiter that also appears in the content — computationally infeasible with // HMAC-SHA256. This check exists as defense-in-depth. func ValidateHeredocContent(content, delimiter string) error { + heredocLog.Printf("Validating heredoc content against delimiter %q (content length: %d)", delimiter, len(content)) if delimiter == "" { return errors.New("heredoc delimiter cannot be empty") } @@ -31,6 +36,7 @@ func ValidateHeredocContent(content, delimiter string) error { return err } if strings.Contains(content, delimiter) { + heredocLog.Printf("Heredoc injection detected: delimiter %q found in content", delimiter) return fmt.Errorf("content contains heredoc delimiter %q — possible injection attempt", delimiter) } return nil @@ -41,13 +47,17 @@ func ValidateHeredocContent(content, delimiter string) error { // single quotes, newlines, carriage returns, or non-printable characters // that could break the generated shell/YAML. func ValidateHeredocDelimiter(delimiter string) error { + heredocLog.Printf("Validating heredoc delimiter %q", delimiter) for _, r := range delimiter { switch { case r == '\'': + heredocLog.Printf("Invalid delimiter %q: contains single quote", delimiter) return fmt.Errorf("heredoc delimiter %q contains single quote", delimiter) case r == '\n', r == '\r': + heredocLog.Printf("Invalid delimiter %q: contains newline", delimiter) return fmt.Errorf("heredoc delimiter %q contains newline", delimiter) case r < 0x20 && r != '\t': + heredocLog.Printf("Invalid delimiter %q: contains non-printable character %U", delimiter, r) return fmt.Errorf("heredoc delimiter %q contains non-printable character %U", delimiter, r) } } diff --git a/pkg/workflow/model_aliases.go b/pkg/workflow/model_aliases.go index 3c95988fc0e..8b50a404ca9 100644 --- a/pkg/workflow/model_aliases.go +++ b/pkg/workflow/model_aliases.go @@ -25,7 +25,13 @@ package workflow -import "maps" +import ( + "maps" + + "github.com/github/gh-aw/pkg/logger" +) + +var modelAliasesLog = logger.New("workflow:model_aliases") // BuiltinModelAliases returns the built-in model alias map that covers the main // model families supported by gh-aw. The returned map is a freshly allocated @@ -138,20 +144,30 @@ func BuiltinModelAliases() map[string][]string { // If both importedModels and frontmatterModels are nil/empty, the builtin aliases are // returned as-is (identical to MergeModelAliases(nil)). func MergeImportedModelAliases(importedModels []map[string][]string, frontmatterModels map[string][]string) map[string][]string { + modelAliasesLog.Printf("Merging model aliases: %d import(s), %d frontmatter override(s)", len(importedModels), len(frontmatterModels)) merged := BuiltinModelAliases() // Layer 2 — imported models (first import to define a key wins among imports). + addedFromImports := 0 for _, importedMap := range importedModels { for k, v := range importedMap { if _, exists := merged[k]; !exists { merged[k] = v + addedFromImports++ } } } + if addedFromImports > 0 { + modelAliasesLog.Printf("Added %d alias(es) from imports", addedFromImports) + } // Layer 3 — main workflow frontmatter always wins. + if len(frontmatterModels) > 0 { + modelAliasesLog.Printf("Applying %d frontmatter alias override(s)", len(frontmatterModels)) + } maps.Copy(merged, frontmatterModels) + modelAliasesLog.Printf("Final alias map has %d entries", len(merged)) return merged } diff --git a/pkg/workflow/model_identifier.go b/pkg/workflow/model_identifier.go index a282548eeed..9683158d343 100644 --- a/pkg/workflow/model_identifier.go +++ b/pkg/workflow/model_identifier.go @@ -51,8 +51,12 @@ import ( "regexp" "strconv" "strings" + + "github.com/github/gh-aw/pkg/logger" ) +var modelIdentifierLog = logger.New("workflow:model_identifier") + // ParsedModelIdentifier holds the components of a parsed model identifier. type ParsedModelIdentifier struct { // Raw is the original unparsed string. @@ -161,6 +165,7 @@ func isAlpha(r rune) bool { return isLetter(r) } // Returns a non-nil *ParsedModelIdentifier on success. // Returns an error (satisfying V-MAF-001 and V-MAF-006) on syntax violations. func ParseModelIdentifier(s string) (*ParsedModelIdentifier, error) { + modelIdentifierLog.Printf("Parsing model identifier: %q", s) if s == "" { return nil, errors.New("model identifier must not be empty") } @@ -180,6 +185,7 @@ func ParseModelIdentifier(s string) (*ParsedModelIdentifier, error) { provider, modelPart, _ := strings.Cut(base, "/") if err := validateProviderToken(provider); err != nil { + modelIdentifierLog.Printf("Invalid provider token %q: %v", provider, err) return nil, err } @@ -187,6 +193,7 @@ func ParseModelIdentifier(s string) (*ParsedModelIdentifier, error) { if strings.Contains(modelPart, "*") { // Glob pattern. + modelIdentifierLog.Printf("Parsing as glob pattern: provider=%q model-glob=%q", provider, modelPart) if err := validateModelGlobToken(modelPart); err != nil { return nil, err } @@ -194,6 +201,7 @@ func ParseModelIdentifier(s string) (*ParsedModelIdentifier, error) { p.IsGlob = true } else { // Exact provider-scoped name. + modelIdentifierLog.Printf("Parsing as provider-scoped: provider=%q model=%q", provider, modelPart) if err := validateModelToken(modelPart); err != nil { return nil, err } @@ -201,6 +209,7 @@ func ParseModelIdentifier(s string) (*ParsedModelIdentifier, error) { } } else { // Bare name. + modelIdentifierLog.Printf("Parsing as bare name: %q", base) if err := validateBareName(base); err != nil { return nil, err } @@ -208,13 +217,16 @@ func ParseModelIdentifier(s string) (*ParsedModelIdentifier, error) { // ── Parse and validate query string ───────────────────────────────────── if rawQuery != "" { + modelIdentifierLog.Printf("Parsing query string: %q", rawQuery) params, err := parseQueryString(rawQuery) if err != nil { return nil, err } p.Params = params + modelIdentifierLog.Printf("Parsed %d query param(s)", len(params)) } + modelIdentifierLog.Printf("Successfully parsed model identifier: provider=%q model=%q isGlob=%v params=%d", p.Provider, p.ModelToken, p.IsGlob, len(p.Params)) return p, nil }