[log] add debug logging to 5 Go packages

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

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
 }

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,13 +28,15 @@ 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")
 	}
 	if err := ValidateHeredocDelimiter(delimiter); err != nil {
 		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)
 		}
 	}

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
 }
 

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,41 +185,48 @@ 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
 		}
 
 		p.Provider = provider
 
 		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
 			}
 			p.ModelToken = modelPart
 			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
 			}
 			p.ModelToken = modelPart
 		}
 	} else {
 		// Bare name.
+		modelIdentifierLog.Printf("Parsing as bare name: %q", base)
 		if err := validateBareName(base); err != nil {
 			return nil, err
 		}
 	}
 
 	// ── 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
 }