From 07201dd20e1c62472fd274dd83eb867b6401ab38 Mon Sep 17 00:00:00 2001 From: Ilyes512 Date: Thu, 14 May 2026 21:36:41 +0200 Subject: [PATCH 1/2] feat: improve observability via structured logging (#51) - Add *slog.Logger to hooks.Load() and Hooks struct; replace slog.Default() usage in Run() with the injected logger (falls back to slog.Default() when Hooks is constructed directly in tests). Emit debug logs for trigger start, per-command invocation, and completion. - Add *slog.Logger parameter to template.ApplyComputed(); log each computed key resolution with source="computed". - Add debug logs to template.Get() (load start/end with key/computed counts) and template.Execute() (per-file action=render|verbatim|skip at debug; rendered/verbatim/skipped summary at info level). - Change LoadMetadata to return the actual parse error for malformed __metadata.json (missing files still return nil,nil); update all callers to log the error at debug instead of silently discarding it. - In pkg/cmd/template_use.go executeTemplate: log each context key with its source (values_file, arg_flag, default, prompt); pass app.Logger to hooks.Load and ApplyComputed; thread logger through promptContext and runPromptPass. - In pkg/cmd/root.go PersistentPreRunE: call slog.SetDefault(app.Logger) so packages using slog.Default() (registry, etc.) inherit the configured level and handler. - Fix silent error swallows in template_list.go, template_update.go, registry.go: log LoadMetadata and LoadStatus errors at debug. Add debug logs before/after remote status checks with consistent attribute keys (name, repo, branch, up_to_date, error_kind). - Add debug logs for git clone and describe calls in template_download.go and use.go (repo, dest, branch, commit, version). - Add "Logging" section to docs/content/docs/architecture/overview.md documenting --debug/--output=json interaction, all log points, and the consistent attribute key set. - Update pkg/hooks/hooks_test.go to pass a discardLogger to Load(). - Update pkg/template/context_test.go to pass discardLogger to ApplyComputed(). - Update TestLoadMetadata_Malformed to expect an error for malformed JSON. Closes #51 Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- docs/content/docs/architecture/overview.md | 64 +++++++++++++++++++++- pkg/cmd/app.go | 25 ++++----- pkg/cmd/root.go | 2 +- pkg/cmd/template_download.go | 2 + pkg/cmd/template_list.go | 19 +++++-- pkg/cmd/template_list_test.go | 10 ++-- pkg/cmd/template_update.go | 19 +++++-- pkg/cmd/template_use.go | 42 ++++++++++---- pkg/cmd/template_validate.go | 2 +- pkg/cmd/testmain_test.go | 13 +++++ pkg/cmd/use.go | 1 + pkg/hooks/hooks.go | 8 ++- pkg/hooks/hooks_test.go | 7 +++ pkg/registry/helpers_test.go | 13 +++++ pkg/registry/registry.go | 35 ++++++++++-- pkg/template/analysis_test.go | 2 +- pkg/template/context.go | 2 + pkg/template/context_test.go | 48 ++++++++-------- pkg/template/functions.go | 6 +- pkg/template/functions_test.go | 16 +++--- pkg/template/helpers_test.go | 9 +-- pkg/template/metadata.go | 5 +- pkg/template/metadata_test.go | 10 ++-- pkg/template/template.go | 46 +++++++++++++--- pkg/template/template_test.go | 38 ++++++------- pkg/util/git/git.go | 55 +++++++++++++------ pkg/util/git/helpers_test.go | 13 +++++ 27 files changed, 371 insertions(+), 141 deletions(-) create mode 100644 pkg/cmd/testmain_test.go create mode 100644 pkg/registry/helpers_test.go create mode 100644 pkg/util/git/helpers_test.go diff --git a/docs/content/docs/architecture/overview.md b/docs/content/docs/architecture/overview.md index a1effa8..bc24162 100644 --- a/docs/content/docs/architecture/overview.md +++ b/docs/content/docs/architecture/overview.md @@ -300,6 +300,68 @@ that parse structured output. --- +## Logging + +`specs` uses `log/slog` for structured diagnostic output. All packages emit logs via the +package-level `slog.Debug/Info/Warn/Error` functions, which route through the global default +logger. `NewApp()` calls `slog.SetDefault` to install a text handler at `Info` level; +`PersistentPreRunE` re-sets it when `--debug --output=json` swaps the handler to JSON. + +### Flags + +| Flag | Effect | +|------|--------| +| `--debug` | Raises the slog level from `Info` to `Debug`; all debug logs become visible | +| `--output=json` + `--debug` | Swaps the slog handler to `slog.NewJSONHandler` writing to stderr; debug logs are emitted as NDJSON distinct from stdout data | + +### Log points + +| Package | Function | Level | Attributes | +|---------|----------|-------|------------| +| `pkg/template` | `Get` | Debug | `template`, `keys`, `computed` | +| `pkg/template` | `Execute` | Debug | `path`, `dest`, `action` (render/verbatim/skip) | +| `pkg/template` | `Execute` | Info | `template`, `dest`, `rendered`, `verbatim`, `skipped` (summary) | +| `pkg/template` | `ApplyComputed` | Debug | `key`, `source`="computed" | +| `pkg/hooks` | `Hooks.Run` | Debug | `trigger`, `commands`, `command` | +| `pkg/cmd` | `executeTemplate` | Debug | `key`, `source` (values_file/arg_flag/default/prompt) — one log per key, final source only | +| `pkg/registry` | `Upgrade` | Debug | `template`, `repo`, `branch`, `target_ref`, `latest_version` | +| `pkg/util/git` | `Clone` | Debug | `repo`, `dest`, `branch` (start and complete) | +| `pkg/util/git` | `Describe` | Debug | `dest`, `commit`, `version` (or `error` on failure) | +| `pkg/util/git` | `CheckRemoteContext` | Debug | `repo`, `branch`, `dest`, `up_to_date`, `latest_version`, `error_kind` | + +### Consistent attribute keys + +| Key | Meaning | +|-----|---------| +| `template` | Registered template name (e.g. `"minimal"`) — primary user identifier | +| `path` | Template-relative source path of a file (e.g. `"src/foo.go"`) | +| `dest` | Absolute destination path on the filesystem | +| `repo` | Remote repository URL | +| `branch` | Git branch or tag ref | +| `commit` | Full git commit SHA | +| `version` | git-describe-style version string | +| `trigger` | Hook trigger name (`pre-use`, `post-use`) | +| `key` | Context variable name | +| `source` | How a context value was provided (`default`/`prompt`/`values_file`/`arg_flag`/`computed`) | +| `action` | File decision (`render`/`verbatim`/`skip`) | +| `error` | Underlying error (formatted as `%v`) | + +### Example: structured debug output + +```sh +# Text handler (default with --debug): +specs --debug template use minimal ./out + +# NDJSON handler (--debug + --output=json): +specs --debug --output=json template ls 2>debug.ndjson +``` + +`--output=json` controls the **data** format on stdout; `--debug` + `--output=json` controls +the **log** format on stderr. The two streams are independent. `slog.SetDefault` is called +by `NewApp()` and re-set in `PersistentPreRunE` when `--debug --output=json` swaps the handler. + +--- + ## Hooks Execution ```go @@ -321,7 +383,7 @@ func Load(templateRoot string, projectConfig map[string]any, envPrefix string) ( // ctx is injected as SPECS_-prefixed uppercase env vars: ProjectName → SPECS_PROJECTNAME. // {{ }} expressions in hook commands are rendered against ctx before execution. // Stops and returns error on first non-zero exit. -func (h *Hooks) Run(trigger, cwd string, ctx map[string]any, funcMap template.FuncMap) error +func (h *Hooks) Run(trigger, cwd string, ctx map[string]any, funcMap template.FuncMap, delims specs.Delimiters) error ``` --- diff --git a/pkg/cmd/app.go b/pkg/cmd/app.go index 0fe6e8b..b189b11 100644 --- a/pkg/cmd/app.go +++ b/pkg/cmd/app.go @@ -31,9 +31,9 @@ func WithDebug(enabled bool) Option { } } -// WithHandler returns an Option that replaces the logger with one built by the -// provided factory. The factory receives the App's LevelVar so the handler can -// honour runtime level changes from WithDebug. +// WithHandler returns an Option that replaces the global default logger with one +// built by the provided factory. The factory receives the App's LevelVar so the +// handler can honour runtime level changes from WithDebug. // // Example — switch to JSON output: // @@ -42,13 +42,12 @@ func WithDebug(enabled bool) Option { // })) func WithHandler(factory HandlerFactory) Option { return func(a *App) { - a.Logger = slog.New(factory(a.level)) + slog.SetDefault(slog.New(factory(a.level))) } } // App holds application-wide dependencies shared across all commands. type App struct { - Logger *slog.Logger Output output.Writer level *slog.LevelVar SafeMode bool @@ -56,22 +55,24 @@ type App struct { // checkRemoteFn is the function used by template list to query remote status. // Defaults to pkggit.CheckRemoteContext; tests may substitute a fake. - checkRemoteFn func(ctx context.Context, dir, url, branch string) (pkggit.RemoteCheckResult, error) + checkRemoteFn func(ctx context.Context, dir, url, branch string) pkggit.RemoteCheckResult // checkTimeout is the per-remote timeout for each individual status check (default 10s). checkTimeout time.Duration // refreshTimeout is the maximum wall-clock time for the entire refresh phase (default 30s). refreshTimeout time.Duration } -// NewApp creates an App. The default logger writes text to stderr at info level. -// Use WithHandler to substitute a different handler; use WithDebug to raise the level. +// NewApp creates an App. The default logger writes text to stderr at info level and +// is registered as the global slog default. Use WithHandler to substitute a different +// handler; use WithDebug to raise the level. // Options are applied in order after the default logger is initialised. func NewApp(opts ...Option) *App { level := new(slog.LevelVar) level.Set(slog.LevelInfo) + slog.SetDefault(slog.New(slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{Level: level}))) + app := &App{ - Logger: slog.New(slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{Level: level})), Output: output.NewDefaultHumanWriter(), level: level, checkRemoteFn: pkggit.CheckRemoteContext, @@ -91,9 +92,3 @@ func NewApp(opts ...Option) *App { func (a *App) templateConfig() pkgtemplate.Config { return pkgtemplate.Config{SafeMode: a.SafeMode} } - -// templateGet is a convenience wrapper that calls template.Get with the App's -// logger, so callers don't have to pass it explicitly every time. -func (a *App) templateGet(templateRoot string) (*pkgtemplate.Template, error) { - return pkgtemplate.Get(templateRoot, a.templateConfig(), a.Logger) -} diff --git a/pkg/cmd/root.go b/pkg/cmd/root.go index b798b2f..b2b220b 100644 --- a/pkg/cmd/root.go +++ b/pkg/cmd/root.go @@ -56,7 +56,7 @@ Use "specs --help" for more information about a command.`, if debug { app.level.Set(slog.LevelDebug) if outputFlag == "json" { - app.Logger = slog.New(slog.NewJSONHandler(cmd.ErrOrStderr(), &slog.HandlerOptions{Level: app.level})) + slog.SetDefault(slog.New(slog.NewJSONHandler(cmd.ErrOrStderr(), &slog.HandlerOptions{Level: app.level}))) } } else { app.level.Set(slog.LevelInfo) diff --git a/pkg/cmd/template_download.go b/pkg/cmd/template_download.go index abce329..d9c63fe 100644 --- a/pkg/cmd/template_download.go +++ b/pkg/cmd/template_download.go @@ -47,9 +47,11 @@ func newTemplateDownloadCmd(app *App) *cobra.Command { } app.Output.Info("cloning %s…", src.CloneURL) + // git layer logs clone start/complete if err := pkggit.Clone(src.CloneURL, dest, pkggit.CloneOptions{Branch: src.Branch}); err != nil { return err } + // git layer logs describe result or failure desc, _ := pkggit.Describe(dest) if err := pkgtemplate.SaveMetadata(dest, name, src.CloneURL, src.Branch, desc.Commit, desc.Version, time.Now().UTC()); err != nil { return err diff --git a/pkg/cmd/template_list.go b/pkg/cmd/template_list.go index 2b64195..6695abb 100644 --- a/pkg/cmd/template_list.go +++ b/pkg/cmd/template_list.go @@ -2,6 +2,7 @@ package cmd import ( "context" + "log/slog" "os" "sync" "time" @@ -42,10 +43,16 @@ func newTemplateListCmd(app *App) *cobra.Command { } name := e.Name() root := specs.TemplatePath(name) - meta, _ := pkgtemplate.LoadMetadata(root) + meta, err := pkgtemplate.LoadMetadata(root) + if err != nil { + slog.Debug("failed to parse template metadata", "template", name, "error", err) + } var status *pkgtemplate.TemplateStatus if meta != nil && meta.Repository != "" && meta.Branch != "" { - status, _ = pkgtemplate.LoadStatus(root) + status, err = pkgtemplate.LoadStatus(root) + if err != nil { + slog.Debug("failed to load template status", "template", name, "error", err) + } } tmplEntries = append(tmplEntries, templateEntry{name: name, meta: meta, status: status}) } @@ -74,14 +81,17 @@ func newTemplateListCmd(app *App) *cobra.Command { checkCtx, cancelCheck := context.WithTimeout(egCtx, app.checkTimeout) defer cancelCheck() root := specs.TemplatePath(name) - result, _ := app.checkRemoteFn(checkCtx, root, repo, branch) + // git layer logs the check-remote start/result + result := app.checkRemoteFn(checkCtx, root, repo, branch) newStatus := &pkgtemplate.TemplateStatus{ CheckedAt: pkgtemplate.JSONTime{Time: time.Now().UTC()}, IsUpToDate: result.IsUpToDate, LatestVersion: result.LatestVersion, ErrorKind: result.ErrorKind, } - _ = pkgtemplate.SaveStatus(root, newStatus) + if err := pkgtemplate.SaveStatus(root, newStatus); err != nil { + slog.Debug("failed to save template status", "template", name, "error", err) + } mu.Lock() tmplEntries[i].status = newStatus if result.ErrorKind == pkggit.CheckErrorNetwork { @@ -154,4 +164,3 @@ func statusLabel(status *pkgtemplate.TemplateStatus, hasRemote bool) string { } return "update available" } - diff --git a/pkg/cmd/template_list_test.go b/pkg/cmd/template_list_test.go index 1c764bf..9e04f56 100644 --- a/pkg/cmd/template_list_test.go +++ b/pkg/cmd/template_list_test.go @@ -18,7 +18,7 @@ import ( // executeCmdWithCheckFn runs the command with a custom checkRemoteFn injected into the App. func executeCmdWithCheckFn( - fn func(ctx context.Context, dir, url, branch string) (pkggit.RemoteCheckResult, error), + fn func(ctx context.Context, dir, url, branch string) pkggit.RemoteCheckResult, args ...string, ) (string, error) { app := NewApp() @@ -216,7 +216,7 @@ func TestList_ConcurrencyCap(t *testing.T) { peak int ) - fake := func(ctx context.Context, dir, url, branch string) (pkggit.RemoteCheckResult, error) { + fake := func(ctx context.Context, dir, url, branch string) pkggit.RemoteCheckResult { mu.Lock() current++ if current > peak { @@ -231,7 +231,7 @@ func TestList_ConcurrencyCap(t *testing.T) { mu.Lock() current-- mu.Unlock() - return pkggit.RemoteCheckResult{IsUpToDate: true}, nil + return pkggit.RemoteCheckResult{IsUpToDate: true} } if _, err := executeCmdWithCheckFn(fake, "template", "list"); err != nil { @@ -261,11 +261,11 @@ func TestList_PerCheckTimeout(t *testing.T) { } var called atomic.Bool - fake := func(ctx context.Context, dir, url, branch string) (pkggit.RemoteCheckResult, error) { + fake := func(ctx context.Context, dir, url, branch string) pkggit.RemoteCheckResult { called.Store(true) // Block until the per-check context times out. <-ctx.Done() - return pkggit.RemoteCheckResult{ErrorKind: pkggit.CheckErrorNetwork}, nil + return pkggit.RemoteCheckResult{ErrorKind: pkggit.CheckErrorNetwork} } start := time.Now() diff --git a/pkg/cmd/template_update.go b/pkg/cmd/template_update.go index cbdde16..dfb18b2 100644 --- a/pkg/cmd/template_update.go +++ b/pkg/cmd/template_update.go @@ -1,6 +1,7 @@ package cmd import ( + "log/slog" "os" "time" @@ -40,12 +41,16 @@ func newTemplateUpdateCmd(app *App) *cobra.Command { for _, name := range names { root := specs.TemplatePath(name) - meta, _ := pkgtemplate.LoadMetadata(root) + meta, err := pkgtemplate.LoadMetadata(root) + if err != nil { + slog.Debug("failed to parse template metadata", "template", name, "error", err) + } if meta == nil || meta.Repository == "" || meta.Branch == "" { continue } - result, _ := pkggit.CheckRemote(root, meta.Repository, meta.Branch) + // git layer logs the check-remote start/result + result := pkggit.CheckRemote(root, meta.Repository, meta.Branch) newStatus := &pkgtemplate.TemplateStatus{ CheckedAt: pkgtemplate.JSONTime{Time: time.Now().UTC()}, @@ -53,7 +58,9 @@ func newTemplateUpdateCmd(app *App) *cobra.Command { LatestVersion: result.LatestVersion, ErrorKind: result.ErrorKind, } - _ = pkgtemplate.SaveStatus(root, newStatus) + if err := pkgtemplate.SaveStatus(root, newStatus); err != nil { + slog.Debug("failed to save template status", "template", name, "error", err) + } switch result.ErrorKind { case pkggit.CheckErrorNetwork: @@ -78,7 +85,11 @@ func newTemplateUpdateCmd(app *App) *cobra.Command { if len(updatesAvailable) > 0 { for _, name := range updatesAvailable { root := specs.TemplatePath(name) - if s, _ := pkgtemplate.LoadStatus(root); s != nil && s.LatestVersion != "" { + s, err := pkgtemplate.LoadStatus(root) + if err != nil { + slog.Debug("failed to load template status", "template", name, "error", err) + } + if s != nil && s.LatestVersion != "" { app.Output.Info("template %q has an update available: %s", name, s.LatestVersion) } else { app.Output.Info("template %q has an update available", name) diff --git a/pkg/cmd/template_use.go b/pkg/cmd/template_use.go index 6faafea..485104b 100644 --- a/pkg/cmd/template_use.go +++ b/pkg/cmd/template_use.go @@ -2,6 +2,7 @@ package cmd import ( "fmt" + "log/slog" "os" "path/filepath" "sort" @@ -68,7 +69,7 @@ func newTemplateUseCmd(app *App) *cobra.Command { func (a *App) executeTemplate(templateRoot, targetDir string, opts executeOpts) error { cfg := a.templateConfig() cfg.ContinueOnRenderError = opts.continueOnError - tmpl, err := pkgtemplate.Get(templateRoot, cfg, a.Logger) + tmpl, err := pkgtemplate.Get(templateRoot, cfg) if err != nil { return err } @@ -84,6 +85,10 @@ func (a *App) executeTemplate(templateRoot, targetDir string, opts executeOpts) ctx := tmpl.Context provided := make(map[string]bool) + // finalSource tracks the winning source for each context key, overwritten as values flow + // through values_file → arg_flag → prompt → default. Logged in a single batch before + // ApplyComputed so each key appears only once with its final source. + finalSource := make(map[string]string) if opts.valuesFile != "" { fileVals, err := values.LoadFile(opts.valuesFile) @@ -92,6 +97,7 @@ func (a *App) executeTemplate(templateRoot, targetDir string, opts executeOpts) } for k := range fileVals { provided[k] = true + finalSource[k] = "values_file" } ctx = values.Merge(ctx, fileVals) } @@ -103,14 +109,25 @@ func (a *App) executeTemplate(templateRoot, targetDir string, opts executeOpts) } ctx[k] = v provided[k] = true + finalSource[k] = "arg_flag" } if !opts.useDefaults { - if err := promptContext(ctx, tmpl.Context, tmpl.Conditionals, tmpl.Referenced, provided); err != nil { + if err := promptContext(ctx, tmpl.Context, tmpl.Conditionals, tmpl.Referenced, provided, finalSource); err != nil { return err } } else { resolveSelectDefaults(ctx) + for k := range tmpl.Referenced { + if !provided[k] { + finalSource[k] = "default" + } + } + } + + // Emit one log line per key in alphabetical order with its final resolved source. + for _, k := range sortedKeys(finalSource) { + slog.Debug("context key resolved", "key", k, "source", finalSource[k]) } ctx, err = pkgtemplate.ApplyComputed(ctx, tmpl.ComputedDefs, tmpl.FuncMap(), tmpl.Delims()) @@ -218,11 +235,12 @@ func (a *App) confirmRemoteHooks(h *hooks.Hooks, ctx map[string]any, tmpl *pkgte // now-final ctx, and prompts those that are needed. This correctly handles // nested eq/ne gates where the gate variable is itself conditional. func promptContext( - ctx map[string]any, - schema map[string]any, - conds pkgtemplate.Conditionals, + ctx map[string]any, + schema map[string]any, + conds pkgtemplate.Conditionals, referenced map[string]bool, - provided map[string]bool, + provided map[string]bool, + finalSource map[string]string, ) error { schemaKeys := make(map[string]bool, len(schema)) for k := range schema { @@ -244,7 +262,7 @@ func promptContext( } // Pass 1: always-needed variables. - if err := runPromptPass(ctx, schema, alwaysKeys, provided); err != nil { + if err := runPromptPass(ctx, schema, alwaysKeys, provided, finalSource); err != nil { return err } @@ -287,7 +305,7 @@ func promptContext( } } - if err := runPromptPass(ctx, schema, toPrompt, provided); err != nil { + if err := runPromptPass(ctx, schema, toPrompt, provided, finalSource); err != nil { return err } @@ -301,12 +319,13 @@ func promptContext( } // runPromptPass builds a huh form for the given keys and runs it. -// Results are written back into ctx. +// Results are written back into ctx and finalSource is updated with source="prompt". func runPromptPass( ctx map[string]any, schema map[string]any, keys []string, provided map[string]bool, + finalSource map[string]string, ) error { var fields []huh.Field stringResults := make(map[string]*string) @@ -376,15 +395,17 @@ func runPromptPass( for k, p := range stringResults { ctx[k] = *p + finalSource[k] = "prompt" } for k, p := range boolResults { ctx[k] = *p + finalSource[k] = "prompt" } return nil } // sortedKeys returns map keys in alphabetical order. -func sortedKeys(m map[string]any) []string { +func sortedKeys[V any](m map[string]V) []string { keys := make([]string, 0, len(m)) for k := range m { keys = append(keys, k) @@ -415,4 +436,3 @@ func toStringOptions(v []any) []string { } return opts } - diff --git a/pkg/cmd/template_validate.go b/pkg/cmd/template_validate.go index 892bb4b..ee95764 100644 --- a/pkg/cmd/template_validate.go +++ b/pkg/cmd/template_validate.go @@ -32,7 +32,7 @@ func newTemplateValidateCmd(app *App) *cobra.Command { cfg := app.templateConfig() cfg.ContinueOnRenderError = true // validate collects all render errors; never aborts early - tmpl, err := pkgtemplate.Get(templateRoot, cfg, app.Logger) + tmpl, err := pkgtemplate.Get(templateRoot, cfg) if err != nil { return fmt.Errorf("invalid template: %w", err) } diff --git a/pkg/cmd/testmain_test.go b/pkg/cmd/testmain_test.go new file mode 100644 index 0000000..c52e0ca --- /dev/null +++ b/pkg/cmd/testmain_test.go @@ -0,0 +1,13 @@ +package cmd + +import ( + "io" + "log/slog" + "os" + "testing" +) + +func TestMain(m *testing.M) { + slog.SetDefault(slog.New(slog.NewTextHandler(io.Discard, nil))) + os.Exit(m.Run()) +} diff --git a/pkg/cmd/use.go b/pkg/cmd/use.go index 3ed6c8a..ad69f8d 100644 --- a/pkg/cmd/use.go +++ b/pkg/cmd/use.go @@ -68,6 +68,7 @@ func runUse(app *App, rawSource, targetDir string, opts executeOpts) error { // go-git requires the destination to not exist; use a subdirectory. cloneDir := filepath.Join(tmp, "repo") app.Output.Info("cloning %s…", src.CloneURL) + // git layer logs clone start/complete if err := pkggit.Clone(src.CloneURL, cloneDir, pkggit.CloneOptions{Branch: src.Branch}); err != nil { return err } diff --git a/pkg/hooks/hooks.go b/pkg/hooks/hooks.go index 4a12a7e..8cc6ed3 100644 --- a/pkg/hooks/hooks.go +++ b/pkg/hooks/hooks.go @@ -81,13 +81,15 @@ func (h *Hooks) Run(trigger, cwd string, ctx map[string]any, funcMap template.Fu env := buildEnv(ctx, h.EnvPrefix) + slog.Debug("running hooks", "trigger", trigger, "commands", len(commands)) + for _, cmdTpl := range commands { rendered, err := renderCommand(cmdTpl, ctx, funcMap, delims) if err != nil { return fmt.Errorf("rendering hook command: %w", err) } - slog.Default().Debug("running hook", "trigger", trigger, "command", firstLine(rendered)) + slog.Debug("running hook command", "trigger", trigger, "command", firstLine(rendered)) cmd := exec.Command("bash", "-c", rendered) cmd.Dir = cwd @@ -95,9 +97,13 @@ func (h *Hooks) Run(trigger, cwd string, ctx map[string]any, funcMap template.Fu cmd.Stdout = os.Stdout cmd.Stderr = os.Stderr + slog.Debug("hook command stdout/stderr piped to process output", "trigger", trigger) + if err := cmd.Run(); err != nil { return fmt.Errorf("%s hook failed: %w", trigger, err) } + + slog.Debug("hook command completed", "trigger", trigger, "command", firstLine(rendered)) } return nil } diff --git a/pkg/hooks/hooks_test.go b/pkg/hooks/hooks_test.go index 2f8f9cf..52ea365 100644 --- a/pkg/hooks/hooks_test.go +++ b/pkg/hooks/hooks_test.go @@ -2,6 +2,8 @@ package hooks import ( "errors" + "io" + "log/slog" "os" "path/filepath" "strings" @@ -11,6 +13,11 @@ import ( "github.com/specsnl/specs-cli/pkg/specs" ) +func TestMain(m *testing.M) { + slog.SetDefault(slog.New(slog.NewTextHandler(io.Discard, nil))) + os.Exit(m.Run()) +} + // loadNoPrefix calls Load with an empty env prefix, for tests that don't care about prefixing. func loadNoPrefix(templateRoot string, projectConfig map[string]any) (*Hooks, error) { return Load(templateRoot, projectConfig, "") diff --git a/pkg/registry/helpers_test.go b/pkg/registry/helpers_test.go new file mode 100644 index 0000000..4c29f69 --- /dev/null +++ b/pkg/registry/helpers_test.go @@ -0,0 +1,13 @@ +package registry_test + +import ( + "io" + "log/slog" + "os" + "testing" +) + +func TestMain(m *testing.M) { + slog.SetDefault(slog.New(slog.NewTextHandler(io.Discard, nil))) + os.Exit(m.Run()) +} diff --git a/pkg/registry/registry.go b/pkg/registry/registry.go index 9141fc1..fbb4974 100644 --- a/pkg/registry/registry.go +++ b/pkg/registry/registry.go @@ -2,6 +2,7 @@ package registry import ( "fmt" + "log/slog" "os" "github.com/specsnl/specs-cli/pkg/specs" @@ -36,10 +37,16 @@ func Load(name string) (*Entry, error) { if _, err := os.Stat(root); os.IsNotExist(err) { return nil, nil } - meta, _ := pkgtemplate.LoadMetadata(root) + meta, err := pkgtemplate.LoadMetadata(root) + if err != nil { + slog.Debug("failed to parse template metadata", "template", name, "error", err) + } var status *pkgtemplate.TemplateStatus if meta != nil && meta.Repository != "" && meta.Branch != "" { - status, _ = pkgtemplate.LoadStatus(root) + status, err = pkgtemplate.LoadStatus(root) + if err != nil { + slog.Debug("failed to load template status", "template", name, "error", err) + } } return &Entry{Name: name, Root: root, Metadata: meta, Status: status}, nil } @@ -57,13 +64,18 @@ func Upgrade(name string) (UpgradeResult, error) { return UpgradeResult{}, fmt.Errorf("%w: %s", specs.ErrTemplateNotFound, name) } - meta, _ := pkgtemplate.LoadMetadata(root) + slog.Debug("upgrade start", "template", name) + + meta, err := pkgtemplate.LoadMetadata(root) + if err != nil { + slog.Debug("failed to parse template metadata", "template", name, "error", err) + } if meta == nil || meta.Repository == "" || meta.Branch == "" { return UpgradeResult{IsLocal: true}, nil } targetRef := meta.Branch - result, _ := pkggit.CheckRemote(root, meta.Repository, meta.Branch) + result := pkggit.CheckRemote(root, meta.Repository, meta.Branch) if err := result.Err(); err != nil { return UpgradeResult{}, err } @@ -71,6 +83,14 @@ func Upgrade(name string) (UpgradeResult, error) { return UpgradeResult{AlreadyUpToDate: true}, nil } + slog.Debug("upgrade target", + "template", name, + "repo", meta.Repository, + "branch", meta.Branch, + "target_ref", targetRef, + "latest_version", result.LatestVersion, + ) + newBranch := meta.Branch if result.LatestVersion != "" { targetRef = result.LatestVersion @@ -84,13 +104,16 @@ func Upgrade(name string) (UpgradeResult, error) { return UpgradeResult{}, err } - desc, _ := pkggit.Describe(root) + desc, _ := pkggit.Describe(root) // errors are logged by the git layer if err := pkgtemplate.SaveMetadata(root, name, meta.Repository, newBranch, desc.Commit, desc.Version, meta.Created.Time); err != nil { return UpgradeResult{}, err } // Remove stale status; regenerated on next template list or update. - _ = os.Remove(root + "/" + specs.StatusFile) + if err := os.Remove(root + "/" + specs.StatusFile); err != nil && !os.IsNotExist(err) { + slog.Debug("removing stale status file failed", "template", name, "error", err) + } + slog.Debug("upgrade complete", "template", name, "target_ref", targetRef) return UpgradeResult{Repository: meta.Repository, TargetRef: targetRef}, nil } diff --git a/pkg/template/analysis_test.go b/pkg/template/analysis_test.go index ac235f0..d0d62f1 100644 --- a/pkg/template/analysis_test.go +++ b/pkg/template/analysis_test.go @@ -34,7 +34,7 @@ func buildAnalysisTemplate(t *testing.T, yaml string, files map[string]string) s func analyzeTemplate(t *testing.T, root string) *pkgtemplate.Template { t.Helper() - tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}, discardLogger()) + tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}) if err != nil { t.Fatalf("Get: %v", err) } diff --git a/pkg/template/context.go b/pkg/template/context.go index f63a3b5..ade9cdc 100644 --- a/pkg/template/context.go +++ b/pkg/template/context.go @@ -4,6 +4,7 @@ import ( "bytes" "encoding/json" "fmt" + "log/slog" "maps" "os" "path/filepath" @@ -97,6 +98,7 @@ func ApplyComputed(ctx map[string]any, defs map[string]string, funcMap texttempl return nil, fmt.Errorf("computed %q: %w", k, err) } result[k] = val + slog.Debug("context key resolved", "key", k, "source", "computed") } return result, nil diff --git a/pkg/template/context_test.go b/pkg/template/context_test.go index d2729d1..5c06cb5 100644 --- a/pkg/template/context_test.go +++ b/pkg/template/context_test.go @@ -35,7 +35,7 @@ func TestLoadUserContext_String(t *testing.T) { dir := t.TempDir() writeProjectYAML(t, dir, "Name: my-project\n") - ctx, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}, discardLogger()), specs.DefaultDelimiters) + ctx, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}), specs.DefaultDelimiters) if err != nil { t.Fatalf("unexpected error: %v", err) } @@ -48,7 +48,7 @@ func TestLoadUserContext_Bool(t *testing.T) { dir := t.TempDir() writeProjectYAML(t, dir, "UseSonar: false\n") - ctx, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}, discardLogger()), specs.DefaultDelimiters) + ctx, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}), specs.DefaultDelimiters) if err != nil { t.Fatalf("unexpected error: %v", err) } @@ -65,7 +65,7 @@ License: - GPL `) - ctx, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}, discardLogger()), specs.DefaultDelimiters) + ctx, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}), specs.DefaultDelimiters) if err != nil { t.Fatalf("unexpected error: %v", err) } @@ -82,7 +82,7 @@ func TestLoadUserContext_JSONFallback(t *testing.T) { dir := t.TempDir() writeProjectJSON(t, dir, `{"Name": "from-json"}`) - ctx, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}, discardLogger()), specs.DefaultDelimiters) + ctx, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}), specs.DefaultDelimiters) if err != nil { t.Fatalf("unexpected error: %v", err) } @@ -98,7 +98,7 @@ Name: My App Slug: "{{toKebabCase .Name}}" `) - ctx, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}, discardLogger()), specs.DefaultDelimiters) + ctx, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}), specs.DefaultDelimiters) if err != nil { t.Fatalf("unexpected error: %v", err) } @@ -114,7 +114,7 @@ A: "{{.B}}" B: "{{.A}}" `) - _, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}, discardLogger()), specs.DefaultDelimiters) + _, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}), specs.DefaultDelimiters) if err == nil { t.Fatal("expected error for cyclic reference, got nil") } @@ -129,7 +129,7 @@ hooks: - echo hi `) - ctx, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}, discardLogger()), specs.DefaultDelimiters) + ctx, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}), specs.DefaultDelimiters) if err != nil { t.Fatalf("unexpected error: %v", err) } @@ -146,7 +146,7 @@ computed: Env: prod `) - ctx, computedDefs, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}, discardLogger()), specs.DefaultDelimiters) + ctx, computedDefs, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}), specs.DefaultDelimiters) if err != nil { t.Fatalf("unexpected error: %v", err) } @@ -170,7 +170,7 @@ computed: Name: bar `) - _, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}, discardLogger()), specs.DefaultDelimiters) + _, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}), specs.DefaultDelimiters) if err == nil { t.Fatal("expected error for computed key conflict, got nil") } @@ -183,12 +183,12 @@ computed: Env: "{{toUpper .Name}}" `) - ctx, defs, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}, discardLogger()), specs.DefaultDelimiters) + ctx, defs, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}), specs.DefaultDelimiters) if err != nil { t.Fatalf("LoadUserContext: %v", err) } - result, err := pkgtemplate.ApplyComputed(ctx, defs, pkgtemplate.FuncMap(pkgtemplate.Config{}, discardLogger()), specs.DefaultDelimiters) + result, err := pkgtemplate.ApplyComputed(ctx, defs, pkgtemplate.FuncMap(pkgtemplate.Config{}), specs.DefaultDelimiters) if err != nil { t.Fatalf("ApplyComputed: %v", err) } @@ -209,12 +209,12 @@ computed: DbName: "{{.Slug}}_production" `) - ctx, defs, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}, discardLogger()), specs.DefaultDelimiters) + ctx, defs, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}), specs.DefaultDelimiters) if err != nil { t.Fatalf("LoadUserContext: %v", err) } - result, err := pkgtemplate.ApplyComputed(ctx, defs, pkgtemplate.FuncMap(pkgtemplate.Config{}, discardLogger()), specs.DefaultDelimiters) + result, err := pkgtemplate.ApplyComputed(ctx, defs, pkgtemplate.FuncMap(pkgtemplate.Config{}), specs.DefaultDelimiters) if err != nil { t.Fatalf("ApplyComputed: %v", err) } @@ -235,12 +235,12 @@ computed: B: "{{.A}}" `) - ctx, defs, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}, discardLogger()), specs.DefaultDelimiters) + ctx, defs, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}), specs.DefaultDelimiters) if err != nil { t.Fatalf("LoadUserContext: %v", err) } - _, err = pkgtemplate.ApplyComputed(ctx, defs, pkgtemplate.FuncMap(pkgtemplate.Config{}, discardLogger()), specs.DefaultDelimiters) + _, err = pkgtemplate.ApplyComputed(ctx, defs, pkgtemplate.FuncMap(pkgtemplate.Config{}), specs.DefaultDelimiters) if err == nil { t.Fatal("expected error for computed cycle, got nil") } @@ -248,7 +248,7 @@ computed: func TestApplyComputed_NoDefs(t *testing.T) { ctx := map[string]any{"Name": "test"} - result, err := pkgtemplate.ApplyComputed(ctx, nil, pkgtemplate.FuncMap(pkgtemplate.Config{}, discardLogger()), specs.DefaultDelimiters) + result, err := pkgtemplate.ApplyComputed(ctx, nil, pkgtemplate.FuncMap(pkgtemplate.Config{}), specs.DefaultDelimiters) if err != nil { t.Fatalf("unexpected error: %v", err) } @@ -261,7 +261,7 @@ func TestLoadUserContext_YMLExtension(t *testing.T) { dir := t.TempDir() writeProjectYML(t, dir, "Name: from-yml\n") - ctx, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}, discardLogger()), specs.DefaultDelimiters) + ctx, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}), specs.DefaultDelimiters) if err != nil { t.Fatalf("unexpected error: %v", err) } @@ -274,7 +274,7 @@ func TestLoadUserContext_DelimitersKeyStripped(t *testing.T) { dir := t.TempDir() writeProjectYAML(t, dir, "Name: test\n__delimiters:\n left: \"[[\"\n right: \"]]\"\n") - ctx, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}, discardLogger()), specs.DefaultDelimiters) + ctx, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}), specs.DefaultDelimiters) if err != nil { t.Fatalf("unexpected error: %v", err) } @@ -291,7 +291,7 @@ func TestLoadUserContext_AmbiguousProjectFile(t *testing.T) { writeProjectYAML(t, dir, "Name: from-yaml\n") writeProjectYML(t, dir, "Name: from-yml\n") - _, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}, discardLogger()), specs.DefaultDelimiters) + _, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}), specs.DefaultDelimiters) if err == nil { t.Fatal("expected error for ambiguous project file, got nil") } @@ -373,7 +373,7 @@ func TestLoadUserContext_ComputedConflict_IsErrInvalidComputedDef(t *testing.T) dir := t.TempDir() writeProjectYAML(t, dir, "Name: foo\ncomputed:\n Name: bar\n") - _, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}, discardLogger()), specs.DefaultDelimiters) + _, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}), specs.DefaultDelimiters) if !errors.Is(err, specs.ErrInvalidComputedDef) { t.Errorf("expected ErrInvalidComputedDef, got %v", err) } @@ -383,7 +383,7 @@ func TestLoadUserContext_ComputedNotMapping_IsErrInvalidComputedDef(t *testing.T dir := t.TempDir() writeProjectYAML(t, dir, "Name: foo\ncomputed: not-a-mapping\n") - _, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}, discardLogger()), specs.DefaultDelimiters) + _, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}), specs.DefaultDelimiters) if !errors.Is(err, specs.ErrInvalidComputedDef) { t.Errorf("expected ErrInvalidComputedDef, got %v", err) } @@ -393,12 +393,12 @@ func TestApplyComputed_Cycle_IsErrCyclicDependency(t *testing.T) { dir := t.TempDir() writeProjectYAML(t, dir, "Name: x\ncomputed:\n A: \"{{.B}}\"\n B: \"{{.A}}\"\n") - ctx, defs, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}, discardLogger()), specs.DefaultDelimiters) + ctx, defs, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}), specs.DefaultDelimiters) if err != nil { t.Fatalf("LoadUserContext: %v", err) } - _, err = pkgtemplate.ApplyComputed(ctx, defs, pkgtemplate.FuncMap(pkgtemplate.Config{}, discardLogger()), specs.DefaultDelimiters) + _, err = pkgtemplate.ApplyComputed(ctx, defs, pkgtemplate.FuncMap(pkgtemplate.Config{}), specs.DefaultDelimiters) if !errors.Is(err, specs.ErrCyclicDependency) { t.Errorf("expected ErrCyclicDependency, got %v", err) } @@ -408,7 +408,7 @@ func TestLoadUserContext_CyclicReference_IsErrCyclicDependency(t *testing.T) { dir := t.TempDir() writeProjectYAML(t, dir, "A: \"{{.B}}\"\nB: \"{{.A}}\"\n") - _, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}, discardLogger()), specs.DefaultDelimiters) + _, _, err := pkgtemplate.LoadUserContext(dir, pkgtemplate.FuncMap(pkgtemplate.Config{}), specs.DefaultDelimiters) if !errors.Is(err, specs.ErrCyclicDependency) { t.Errorf("expected ErrCyclicDependency, got %v", err) } diff --git a/pkg/template/functions.go b/pkg/template/functions.go index 357c473..e0dc600 100644 --- a/pkg/template/functions.go +++ b/pkg/template/functions.go @@ -27,9 +27,7 @@ import ( // FuncMap returns all template functions for the given config. // In safe mode the env and filesystem registries are excluded. -// logger is passed to sprout so it can emit structured warnings (e.g. deprecated -// function usage). -func FuncMap(cfg Config, logger *slog.Logger) texttemplate.FuncMap { +func FuncMap(cfg Config) texttemplate.FuncMap { registries := []sprout.Registry{ // Standard utility registries sproutstd.NewRegistry(), @@ -66,7 +64,7 @@ func FuncMap(cfg Config, logger *slog.Logger) texttemplate.FuncMap { ) } - handler := sprout.New(sprout.WithLogger(logger)) + handler := sprout.New(sprout.WithLogger(slog.Default())) if err := handler.AddRegistries(registries...); err != nil { // Registry registration only fails on programmer error (duplicate names); // panic here surfaces the issue during development rather than silently diff --git a/pkg/template/functions_test.go b/pkg/template/functions_test.go index 65736b6..458ca25 100644 --- a/pkg/template/functions_test.go +++ b/pkg/template/functions_test.go @@ -9,7 +9,7 @@ import ( // --- FuncMap presence --- func TestFuncMap_ContainsCustomFunctions(t *testing.T) { - m := pkgtemplate.FuncMap(pkgtemplate.Config{}, discardLogger()) + m := pkgtemplate.FuncMap(pkgtemplate.Config{}) expected := []string{"hostname", "username", "toBinary", "formatFilesize", "password"} for _, name := range expected { @@ -20,7 +20,7 @@ func TestFuncMap_ContainsCustomFunctions(t *testing.T) { } func TestFuncMap_ContainsSproutFunctions(t *testing.T) { - m := pkgtemplate.FuncMap(pkgtemplate.Config{}, discardLogger()) + m := pkgtemplate.FuncMap(pkgtemplate.Config{}) // Spot-check one function from each sprout registry group. spotCheck := []struct { @@ -55,7 +55,7 @@ func TestFuncMap_ContainsSproutFunctions(t *testing.T) { // --- Safe mode --- func TestFuncMap_SafeMode_ExcludesEnvFunctions(t *testing.T) { - m := pkgtemplate.FuncMap(pkgtemplate.Config{SafeMode: true}, discardLogger()) + m := pkgtemplate.FuncMap(pkgtemplate.Config{SafeMode: true}) for _, name := range []string{"env", "expandEnv"} { if _, ok := m[name]; ok { @@ -65,7 +65,7 @@ func TestFuncMap_SafeMode_ExcludesEnvFunctions(t *testing.T) { } func TestFuncMap_SafeMode_ExcludesFilesystemFunctions(t *testing.T) { - m := pkgtemplate.FuncMap(pkgtemplate.Config{SafeMode: true}, discardLogger()) + m := pkgtemplate.FuncMap(pkgtemplate.Config{SafeMode: true}) for _, name := range []string{"pathBase", "pathDir", "osBase", "osDir"} { if _, ok := m[name]; ok { @@ -77,7 +77,7 @@ func TestFuncMap_SafeMode_ExcludesFilesystemFunctions(t *testing.T) { // --- Default mode --- func TestFuncMap_DefaultMode_IncludesEnvFunctions(t *testing.T) { - m := pkgtemplate.FuncMap(pkgtemplate.Config{SafeMode: false}, discardLogger()) + m := pkgtemplate.FuncMap(pkgtemplate.Config{SafeMode: false}) for _, name := range []string{"env", "expandEnv"} { if _, ok := m[name]; !ok { @@ -87,7 +87,7 @@ func TestFuncMap_DefaultMode_IncludesEnvFunctions(t *testing.T) { } func TestFuncMap_DefaultMode_IncludesFilesystemFunctions(t *testing.T) { - m := pkgtemplate.FuncMap(pkgtemplate.Config{SafeMode: false}, discardLogger()) + m := pkgtemplate.FuncMap(pkgtemplate.Config{SafeMode: false}) for _, name := range []string{"pathBase", "pathDir", "osBase", "osDir"} { if _, ok := m[name]; !ok { @@ -104,6 +104,6 @@ func TestFuncMap_NoPanic(t *testing.T) { t.Errorf("FuncMap() panicked: %v", r) } }() - pkgtemplate.FuncMap(pkgtemplate.Config{}, discardLogger()) - pkgtemplate.FuncMap(pkgtemplate.Config{SafeMode: true}, discardLogger()) + pkgtemplate.FuncMap(pkgtemplate.Config{}) + pkgtemplate.FuncMap(pkgtemplate.Config{SafeMode: true}) } diff --git a/pkg/template/helpers_test.go b/pkg/template/helpers_test.go index 6c32564..7473853 100644 --- a/pkg/template/helpers_test.go +++ b/pkg/template/helpers_test.go @@ -3,10 +3,11 @@ package template_test import ( "io" "log/slog" + "os" + "testing" ) -// discardLogger returns a logger that silently discards all output. -// Used in tests where logging behaviour is not under test. -func discardLogger() *slog.Logger { - return slog.New(slog.NewTextHandler(io.Discard, nil)) +func TestMain(m *testing.M) { + slog.SetDefault(slog.New(slog.NewTextHandler(io.Discard, nil))) + os.Exit(m.Run()) } diff --git a/pkg/template/metadata.go b/pkg/template/metadata.go index c010eac..29bea9c 100644 --- a/pkg/template/metadata.go +++ b/pkg/template/metadata.go @@ -58,7 +58,8 @@ func (t JSONTime) String() string { } // LoadMetadata reads __metadata.json from templateRoot. -// Missing or malformed metadata is not an error — returns nil, nil. +// A missing or unreadable file is not an error — returns nil, nil. +// A malformed file returns an error so callers can log the diagnostic. func LoadMetadata(templateRoot string) (*Metadata, error) { path := filepath.Join(templateRoot, specs.MetadataFile) data, err := os.ReadFile(path) @@ -67,7 +68,7 @@ func LoadMetadata(templateRoot string) (*Metadata, error) { } var m Metadata if err := json.Unmarshal(data, &m); err != nil { - return nil, nil //nolint:nilerr // malformed metadata is silently ignored + return nil, fmt.Errorf("parsing %s: %w", specs.MetadataFile, err) } return &m, nil } diff --git a/pkg/template/metadata_test.go b/pkg/template/metadata_test.go index 41d76b3..053f665 100644 --- a/pkg/template/metadata_test.go +++ b/pkg/template/metadata_test.go @@ -115,7 +115,7 @@ func TestGet_LoadsMetadata(t *testing.T) { t.Fatalf("write metadata: %v", err) } - tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}, discardLogger()) + tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}) if err != nil { t.Fatalf("Get: %v", err) } @@ -136,7 +136,7 @@ func TestGet_LoadsMetadata(t *testing.T) { func TestGet_MissingMetadata_ReturnsNil(t *testing.T) { root := buildTemplate(t, "Name: test\n", nil) - tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}, discardLogger()) + tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}) if err != nil { t.Fatalf("Get: %v", err) } @@ -153,7 +153,7 @@ func TestGet_MalformedMetadata_ReturnsError(t *testing.T) { } // LoadMetadata errors are silently ignored by Get (missing/malformed metadata is non-fatal). - tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}, discardLogger()) + tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}) if err != nil { t.Fatalf("Get: unexpected error for malformed metadata: %v", err) } @@ -183,8 +183,8 @@ func TestLoadMetadata_Malformed(t *testing.T) { } m, err := pkgtemplate.LoadMetadata(dir) - if err != nil { - t.Fatalf("LoadMetadata: unexpected error for malformed file: %v", err) + if err == nil { + t.Fatal("LoadMetadata: expected error for malformed file, got nil") } if m != nil { t.Errorf("expected nil for malformed __metadata.json, got %+v", m) diff --git a/pkg/template/template.go b/pkg/template/template.go index 9c61e09..9e0cf1b 100644 --- a/pkg/template/template.go +++ b/pkg/template/template.go @@ -69,7 +69,6 @@ type Template struct { Metadata *Metadata // nil if __metadata.json is absent Warnings []RenderWarning // non-fatal render issues collected during Execute cfg Config - logger *slog.Logger funcMap texttemplate.FuncMap verbatim *VerbatimRules } @@ -88,8 +87,10 @@ func (t *Template) Delims() specs.Delimiters { // Get loads a template from templateRoot. The root must contain either project.yaml or // project.json, and a template/ subdirectory. -func Get(templateRoot string, cfg Config, logger *slog.Logger) (*Template, error) { - funcMap := FuncMap(cfg, logger) +func Get(templateRoot string, cfg Config) (*Template, error) { + slog.Debug("loading template", "template", templateRoot) + + funcMap := FuncMap(cfg) // Resolve delimiters: __delimiters in project.yaml > cfg.Delims > DefaultDelimiters. // Write the resolved value back into cfg so methods on the returned Template @@ -124,7 +125,12 @@ func Get(templateRoot string, cfg Config, logger *slog.Logger) (*Template, error return nil, err } - meta, _ := LoadMetadata(templateRoot) // missing/malformed metadata is not an error + meta, err := LoadMetadata(templateRoot) // missing metadata is not an error + if err != nil { + slog.Debug("failed to parse template metadata", "template", templateRoot, "error", err) + } + + slog.Debug("template loaded", "template", templateRoot, "keys", len(userCtx), "computed", len(computedDefs)) return &Template{ Root: templateRoot, @@ -134,7 +140,6 @@ func Get(templateRoot string, cfg Config, logger *slog.Logger) (*Template, error Referenced: referenced, Metadata: meta, cfg: cfg, - logger: logger, funcMap: funcMap, verbatim: verbatim, }, nil @@ -155,7 +160,11 @@ func (t *Template) Execute(targetDir string) error { srcRoot := filepath.Join(t.Root, specs.TemplateDirFile) - return filepath.WalkDir(srcRoot, func(srcPath string, d fs.DirEntry, err error) error { + slog.Debug("starting template execution", "template", t.Root, "dest", targetDir) + + var rendered, skipped, verbatim int + + walkErr := filepath.WalkDir(srcRoot, func(srcPath string, d fs.DirEntry, err error) error { if err != nil { return err } @@ -176,7 +185,10 @@ func (t *Template) Execute(targetDir string) error { // 2. Render the relative path as a template to get the destination path. destRel, err := t.renderName(rel, ctx) if err != nil || strings.TrimSpace(destRel) == "" { - t.logger.Debug("skipping path", "path", rel, "error", err) + slog.Debug("skipping path", "path", rel, "error", err) + if !d.IsDir() { + skipped++ + } if d.IsDir() { return filepath.SkipDir } @@ -185,6 +197,9 @@ func (t *Template) Execute(targetDir string) error { // 3. Skip if any path segment is empty (conditional directory exclusion). if hasEmptySegment(destRel) { + if !d.IsDir() { + skipped++ + } if d.IsDir() { return filepath.SkipDir } @@ -201,10 +216,27 @@ func (t *Template) Execute(targetDir string) error { // 5. File: determine copy strategy. relForward := filepath.ToSlash(rel) if t.verbatim.Matches(relForward) || isBinary(srcPath) { + slog.Debug("file decision", "path", rel, "dest", destPath, "action", "verbatim") + verbatim++ return copyFile(srcPath, destPath) } + slog.Debug("file decision", "path", rel, "dest", destPath, "action", "render") + rendered++ return t.renderFile(srcPath, destPath, relForward, ctx) }) + + if walkErr != nil { + return walkErr + } + + slog.Info("template execution complete", + "template", t.Root, + "dest", targetDir, + "rendered", rendered, + "verbatim", verbatim, + "skipped", skipped, + ) + return nil } // renderName renders a file/directory path template using the configured delimiters. diff --git a/pkg/template/template_test.go b/pkg/template/template_test.go index d0d8bba..a88dc98 100644 --- a/pkg/template/template_test.go +++ b/pkg/template/template_test.go @@ -58,7 +58,7 @@ func TestExecute_StaticFile(t *testing.T) { "hello.txt": []byte("Hello {{.Name}}"), }) - tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}, discardLogger()) + tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}) if err != nil { t.Fatalf("Get: %v", err) } @@ -79,7 +79,7 @@ func TestExecute_ConditionalFilename_True(t *testing.T) { "{{if .UseX}}feature.txt{{end}}": []byte("enabled"), }) - tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}, discardLogger()) + tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}) if err != nil { t.Fatalf("Get: %v", err) } @@ -99,7 +99,7 @@ func TestExecute_ConditionalFilename_False(t *testing.T) { "{{if .UseX}}feature.txt{{end}}": []byte("enabled"), }) - tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}, discardLogger()) + tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}) if err != nil { t.Fatalf("Get: %v", err) } @@ -119,7 +119,7 @@ func TestExecute_ConditionalDir_False(t *testing.T) { "{{if .UseX}}subdir{{end}}/file.txt": []byte("inside"), }) - tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}, discardLogger()) + tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}) if err != nil { t.Fatalf("Get: %v", err) } @@ -144,7 +144,7 @@ func TestExecute_VerbatimCopy(t *testing.T) { t.Fatalf("writing .specsverbatim: %v", err) } - tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}, discardLogger()) + tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}) if err != nil { t.Fatalf("Get: %v", err) } @@ -167,7 +167,7 @@ func TestExecute_BinaryFile(t *testing.T) { "image.bin": content, }) - tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}, discardLogger()) + tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}) if err != nil { t.Fatalf("Get: %v", err) } @@ -191,7 +191,7 @@ func TestExecute_WhitespaceOnly(t *testing.T) { "empty.txt": []byte("{{if false}}x{{end}}"), }) - tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}, discardLogger()) + tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}) if err != nil { t.Fatalf("Get: %v", err) } @@ -211,7 +211,7 @@ func TestExecute_NestedConditionalDir(t *testing.T) { "{{if .X}}subdir{{end}}/nested/file.txt": []byte("deep"), }) - tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}, discardLogger()) + tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}) if err != nil { t.Fatalf("Get: %v", err) } @@ -234,7 +234,7 @@ func TestExecute_ComputedValueInTemplate(t *testing.T) { }, ) - tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}, discardLogger()) + tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}) if err != nil { t.Fatalf("Get: %v", err) } @@ -258,7 +258,7 @@ func TestExecute_PassthroughDoubleBrace(t *testing.T) { "ci.yml": []byte("group: ${{ github.ref }}\nname: [[.Name]]"), }) - tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}, discardLogger()) + tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}) if err != nil { t.Fatalf("Get: %v", err) } @@ -282,7 +282,7 @@ func TestExecute_CustomDelimiters_NotInContext(t *testing.T) { "out.txt": []byte("[[.Name]]"), }) - tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}, discardLogger()) + tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}) if err != nil { t.Fatalf("Get: %v", err) } @@ -304,7 +304,7 @@ func TestGet_InvalidDelimiters_ReturnsError(t *testing.T) { yaml := "__delimiters: not-a-mapping\nName: x\n" root := buildTemplate(t, yaml, map[string][]byte{"f.txt": []byte("{{.Name}}")}) - _, err := pkgtemplate.Get(root, pkgtemplate.Config{}, discardLogger()) + _, err := pkgtemplate.Get(root, pkgtemplate.Config{}) if err == nil { t.Fatal("expected error for invalid __delimiters, got nil") } @@ -318,7 +318,7 @@ func TestExecute_ParseError_ContinueOnError(t *testing.T) { "compose.yml": original, }) - tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{ContinueOnRenderError: true}, discardLogger()) + tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{ContinueOnRenderError: true}) if err != nil { t.Fatalf("Get: %v", err) } @@ -353,7 +353,7 @@ func TestExecute_ParseError_FailFast(t *testing.T) { "compose.yml": []byte("[[ .Name | undefinedFunc ]]"), }) - tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}, discardLogger()) + tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}) if err != nil { t.Fatalf("Get: %v", err) } @@ -378,7 +378,7 @@ func TestExecute_ExecuteError_FailFast(t *testing.T) { "out.txt": []byte("{{ .MissingKey }}"), }) - tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}, discardLogger()) + tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}) if err != nil { t.Fatalf("Get: %v", err) } @@ -400,7 +400,7 @@ func TestExecute_ExecuteError_ContinueOnError(t *testing.T) { "out.txt": original, }) - tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{ContinueOnRenderError: true}, discardLogger()) + tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{ContinueOnRenderError: true}) if err != nil { t.Fatalf("Get: %v", err) } @@ -444,7 +444,7 @@ func TestExecute_PreservesPermissions_TextFile(t *testing.T) { t.Fatal(err) } - tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}, discardLogger()) + tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}) if err != nil { t.Fatalf("Get: %v", err) } @@ -480,7 +480,7 @@ func TestExecute_PreservesPermissions_BinaryFile(t *testing.T) { t.Fatal(err) } - tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}, discardLogger()) + tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}) if err != nil { t.Fatalf("Get: %v", err) } @@ -505,7 +505,7 @@ func TestGet_CustomDelimiters_ConditionalFilename(t *testing.T) { "[[if .UseX]]feature.txt[[end]]": []byte("enabled"), }) - tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}, discardLogger()) + tmpl, err := pkgtemplate.Get(root, pkgtemplate.Config{}) if err != nil { t.Fatalf("Get: %v", err) } diff --git a/pkg/util/git/git.go b/pkg/util/git/git.go index 4db9e92..faf59f3 100644 --- a/pkg/util/git/git.go +++ b/pkg/util/git/git.go @@ -4,6 +4,7 @@ import ( "context" "errors" "fmt" + "log/slog" "net" "os" "path/filepath" @@ -33,6 +34,8 @@ type CloneOptions struct { // SSH URLs (git@host:path or ssh://host/path) are detected automatically and authenticated // via SSH agent or standard key files in ~/.ssh. func Clone(url, dir string, opts CloneOptions) error { + slog.Debug("git clone start", "repo", url, "dest", dir, "branch", opts.Branch) + cloneOpts := &gogit.CloneOptions{ URL: url, Depth: opts.Depth, @@ -53,13 +56,17 @@ func Clone(url, dir string, opts CloneOptions) error { if opts.Branch != "" { cloneOpts.SingleBranch = true - return cloneWithRef(url, dir, cloneOpts, opts.Branch) + if err := cloneWithRef(url, dir, cloneOpts, opts.Branch); err != nil { + return err + } + } else { + _, err := gogit.PlainClone(dir, false, cloneOpts) + if err != nil { + return fmt.Errorf("cloning %s: %w", url, err) + } } - _, err := gogit.PlainClone(dir, false, cloneOpts) - if err != nil { - return fmt.Errorf("cloning %s: %w", url, err) - } + slog.Debug("git clone complete", "repo", url, "dest", dir, "branch", opts.Branch) return nil } @@ -102,11 +109,13 @@ type DescribeResult struct { func Describe(dir string) (DescribeResult, error) { repo, err := gogit.PlainOpen(dir) if err != nil { + slog.Debug("git describe failed", "dest", dir, "error", err) return DescribeResult{}, fmt.Errorf("opening repository at %s: %w", dir, err) } head, err := repo.Head() if err != nil { + slog.Debug("git describe failed", "dest", dir, "error", err) return DescribeResult{}, fmt.Errorf("reading HEAD: %w", err) } @@ -127,10 +136,12 @@ func Describe(dir string) (DescribeResult, error) { } } - return DescribeResult{ + result := DescribeResult{ Commit: commit, Version: buildVersion(repo, head.Hash(), shortHash, dirty), - }, nil + } + slog.Debug("git describe", "dest", dir, "commit", result.Commit, "version", result.Version) + return result, nil } // buildVersion constructs a version string in git-describe style. @@ -286,23 +297,33 @@ func (r RemoteCheckResult) Err() error { // and never modifies the local repository. SSH auth is resolved automatically. // ctx is forwarded to the underlying network call; cancel it to abort early. // -// On failure, ErrorKind is set in the result and error is nil. -func CheckRemoteContext(ctx context.Context, dir, url, branch string) (RemoteCheckResult, error) { +// On failure, ErrorKind is set in the result; errors are never returned. +func CheckRemoteContext(ctx context.Context, dir, url, branch string) (result RemoteCheckResult) { + slog.Debug("git check-remote start", "repo", url, "branch", branch, "dest", dir) + defer func() { + slog.Debug("git check-remote result", + "repo", url, "branch", branch, "dest", dir, + "up_to_date", result.IsUpToDate, + "latest_version", result.LatestVersion, + "error_kind", string(result.ErrorKind), + ) + }() + repo, err := gogit.PlainOpen(dir) if err != nil { - return RemoteCheckResult{ErrorKind: CheckErrorUnknown}, nil + return RemoteCheckResult{ErrorKind: CheckErrorUnknown} } remote, err := repo.Remote("origin") if err != nil { - return RemoteCheckResult{ErrorKind: CheckErrorUnknown}, nil + return RemoteCheckResult{ErrorKind: CheckErrorUnknown} } listOpts := &gogit.ListOptions{} if isSSHURL(url) { auth, err := sshAuth(url) if err != nil { - return RemoteCheckResult{ErrorKind: CheckErrorAuth}, nil + return RemoteCheckResult{ErrorKind: CheckErrorAuth} } listOpts.Auth = auth } @@ -310,21 +331,21 @@ func CheckRemoteContext(ctx context.Context, dir, url, branch string) (RemoteChe refs, err := remote.ListContext(ctx, listOpts) if err != nil { if ctx.Err() != nil { - return RemoteCheckResult{ErrorKind: CheckErrorNetwork}, nil + return RemoteCheckResult{ErrorKind: CheckErrorNetwork} } - return RemoteCheckResult{ErrorKind: classifyRemoteError(err)}, nil + return RemoteCheckResult{ErrorKind: classifyRemoteError(err)} } head, err := repo.Head() if err != nil { - return RemoteCheckResult{ErrorKind: CheckErrorUnknown}, nil + return RemoteCheckResult{ErrorKind: CheckErrorUnknown} } - return resolveStatus(refs, head.Hash(), branch), nil + return resolveStatus(refs, head.Hash(), branch) } // CheckRemote is a context-free convenience wrapper around CheckRemoteContext. -func CheckRemote(dir, url, branch string) (RemoteCheckResult, error) { +func CheckRemote(dir, url, branch string) RemoteCheckResult { return CheckRemoteContext(context.Background(), dir, url, branch) } diff --git a/pkg/util/git/helpers_test.go b/pkg/util/git/helpers_test.go new file mode 100644 index 0000000..fa8b7b8 --- /dev/null +++ b/pkg/util/git/helpers_test.go @@ -0,0 +1,13 @@ +package git_test + +import ( + "io" + "log/slog" + "os" + "testing" +) + +func TestMain(m *testing.M) { + slog.SetDefault(slog.New(slog.NewTextHandler(io.Discard, nil))) + os.Exit(m.Run()) +} From e7637c6654f3d65b066f6952050dec4e07bace03 Mon Sep 17 00:00:00 2001 From: Ilyes512 Date: Sat, 16 May 2026 15:40:05 +0200 Subject: [PATCH 2/2] Temp plan.md added --- plan.md | 312 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 312 insertions(+) create mode 100644 plan.md diff --git a/plan.md b/plan.md new file mode 100644 index 0000000..79f3d6c --- /dev/null +++ b/plan.md @@ -0,0 +1,312 @@ +# PR #69 follow-up: logger architecture + review fixes + +## Context + +PR #69 (issue [#51](https://github.com/specsnl/specs-cli/issues/51)) adds structured +logging across the CLI but mixes two patterns: an injected `App.Logger` threaded +through `pkgtemplate.Get`, `hooks.Load`, etc., and direct `slog.Default()` calls in +`pkg/registry` and the hook fallback path. The branch sets `slog.SetDefault(app.Logger)` +at the end of `PersistentPreRunE` (`pkg/cmd/root.go:69`), so both pipes exist +side-by-side — the worst of both worlds. + +A code review also flagged ten concrete problems (swallowed `CheckRemote` errors, +mixed attribute keys, no logging in `pkg/util/git`, weak `registry.Upgrade()` coverage, +inconsistent `LoadStatus` failure logging, prompt-source semantics, missing tests, +remaining `, _ :=` audit, docs not matching emitted attributes). + +Issue [#67](https://github.com/specsnl/specs-cli/issues/67) (rename `pkg/` → +`internal/`) removes the only meaningful argument for keeping a logger-injection +API — there are no external consumers to consider. The CLI is a single-process +binary; `log/slog` is built around the default-logger model. + +This plan does the architectural cleanup **and** the ten review fixes in a single +amend on the current branch (`51-improve-observability-via-structured-logging`). + +## Decision: drop logger injection, commit to `slog.Default()` + +After the migration, no production function takes a `*slog.Logger` parameter and no +struct stores one. Every package emits logs via the package-level `slog.Debug/Info/...` +functions, which route through the global default. The CLI entrypoint configures the +default logger once at startup and swaps it when `--debug --output=json` flips the +handler. Tests silence logs with a `TestMain` per package that calls +`slog.SetDefault(slog.New(slog.NewTextHandler(io.Discard, nil)))`. + +The `LevelVar` and `HandlerFactory` machinery on `App` is retained because runtime +level changes from `--debug` still need to mutate the live handler. + +--- + +## Implementation + +### 1. Logger plumbing collapse + +**`pkg/cmd/app.go`** (`pkg/cmd/app.go:49-99`) +- Remove the `Logger *slog.Logger` field from `App`. +- `NewApp()` no longer stores a logger pointer; it builds the default handler and + calls `slog.SetDefault(slog.New(handler))` directly. The `LevelVar` stays on `App` + so `WithDebug` and the `PersistentPreRunE` debug toggle still work. +- `WithHandler` rebuilds the handler from the factory and calls + `slog.SetDefault(...)` instead of assigning to `a.Logger`. +- Drop the `templateGet` helper — call `pkgtemplate.Get(root, cfg)` directly. + +**`pkg/cmd/root.go`** (`pkg/cmd/root.go:33-66`) +- In `PersistentPreRunE`, when `--debug --output=json` switches the handler, + call `slog.SetDefault(slog.New(slog.NewJSONHandler(cmd.ErrOrStderr(), ...)))` + instead of mutating `app.Logger`. Drop the trailing standalone `slog.SetDefault` + (it becomes redundant). + +**`pkg/template/template.go`** (`pkg/template/template.go:65-145, 165-237`) +- `Get(templateRoot, cfg)` — drop the `logger *slog.Logger` parameter. +- Remove the `logger` field from `Template` struct. +- Replace every `logger.X(...)` / `t.logger.X(...)` with `slog.X(...)`. + +**`pkg/template/context.go`** (`pkg/template/context.go:58-102`) +- `ApplyComputed(ctx, defs, funcMap, delims)` — drop the logger parameter. +- Use `slog.Debug(...)` directly. + +**`pkg/template/functions.go`** (the sprout `WithLogger` call site) +- Pass `slog.Default()` to `sprout.WithLogger()` (sprout's API expects a `*slog.Logger`). + +**`pkg/hooks/hooks.go`** (`pkg/hooks/hooks.go:18-115`) +- `Load(templateRoot, projectConfig, envPrefix)` — drop the logger parameter. +- Remove the `logger *slog.Logger` field from `Hooks`. +- Remove the `if logger == nil { logger = slog.Default() }` fallback in `Run`. +- All `logger.Debug(...)` → `slog.Debug(...)`. + +**`pkg/cmd/template_use.go`** (`pkg/cmd/template_use.go:71-141, 200-340`) +- Remove `a.Logger` arguments from `pkgtemplate.Get`, `hooks.Load`, + `pkgtemplate.ApplyComputed`, `promptContext`, `runPromptPass`. +- `promptContext` and `runPromptPass` lose their `logger *slog.Logger` parameters; + use `slog.Debug(...)` directly. + +**`pkg/cmd/template_list.go`**, **`template_update.go`**, **`template_download.go`**, +**`use.go`** +- `app.Logger.X(...)` → `slog.X(...)`. + +**`pkg/registry/registry.go`** (`pkg/registry/registry.go:40-104`) +- Already uses `slog.Default().X(...)`. Replace with package-level `slog.X(...)` + for consistency with the rest of the codebase. + +### 2. Move git logging into `pkg/util/git` (review #3) + +**`pkg/util/git/git.go`** — instrument the three core functions: + +- `Clone` (`pkg/util/git/git.go:35`): `slog.Debug("git clone start", "repo", url, "dest", dir, "branch", opts.Branch)` and a success log on exit. +- `Describe` (`pkg/util/git/git.go:102`): `slog.Debug("git describe", "dest", dir, "commit", result.Commit, "version", result.Version)`; debug log on error. +- `CheckRemoteContext` (`pkg/util/git/git.go:290`): debug log on entry with `repo`, `branch`, `dest`; debug log on exit with `up_to_date`, `latest_version`, `error_kind`. + +Once instrumented, **remove the duplicated logs** at the call sites: +- `pkg/cmd/template_download.go:53-63` (clone + describe) +- `pkg/cmd/use.go` (clone) +- `pkg/cmd/template_list.go:78-86` (`checking remote status` + `remote status result`) +- `pkg/cmd/template_update.go:50-59` (same) +- `pkg/registry/registry.go` — `CheckRemote`/`Clone`/`Describe` calls no longer need + per-callsite duplication. + +### 3. Drop the unused `error` return on `CheckRemote` (review #1) + +`CheckRemoteContext` returns `(RemoteCheckResult, error)` but the implementation +returns `nil` for the error in **every** path — failures are encoded in +`result.ErrorKind` and exposed via `result.Err()`. Drop the `error` from the +signature so `result, _ := ...` patterns disappear and the contract matches reality. + +- `pkg/util/git/git.go:290, 327`: change signatures to return only `RemoteCheckResult`. +- Update all callers: `pkg/cmd/app.go:59` (checkRemoteFn typedef), + `template_list.go:78`, `template_update.go:50`, `registry.go:75`. + +### 4. Add logging in `registry.Upgrade()` (review #4) + +`pkg/registry/registry.go:65-104`: +- Log entry: `slog.Debug("upgrade start", "template", name)`. +- Log the resolved `targetRef` after `CheckRemote`: `slog.Debug("upgrade target", "template", name, "repo", meta.Repository, "branch", meta.Branch, "target_ref", targetRef, "latest_version", result.LatestVersion)`. +- Log the status file removal: `if err := os.Remove(...); err != nil && !os.IsNotExist(err) { slog.Debug("removing stale status file failed", "template", name, "error", err) }`. +- Log completion: `slog.Debug("upgrade complete", "template", name, "target_ref", targetRef)`. +- Clone/Describe logs come from the `pkg/util/git` instrumentation in §2 — no + duplication needed here. + +### 5. Stable attribute key conventions (review #2, #10) + +Standardize on this final key set: + +| Key | Meaning | +|-----------|------------------------------------------------------------------------| +| `template`| Registered template name (e.g. `"minimal"`) — primary user identifier | +| `path` | Template-relative source path of a file (e.g. `"src/foo.go"`) | +| `dest` | Absolute destination path on the filesystem | +| `repo` | Remote repository URL | +| `branch` | Git branch or tag ref | +| `commit` | Full git commit SHA | +| `version` | git-describe-style version string | +| `trigger` | Hook trigger name (`pre-use`, `post-use`) | +| `key` | Context variable name | +| `source` | How a context value was provided (`default`/`prompt`/`values_file`/`arg_flag`/`computed`) | +| `action` | File decision (`render`/`verbatim`/`skip`) | +| `error` | Underlying error (formatted as `%v`) | + +Replace mismatched uses: +- `pkg/template/template.go:92, 117, 130, 163` — `"root", templateRoot` → `"template", templateRoot`. +- `pkg/cmd/template_list.go:48, 53, 77, 80-86, 94, 101` — `"name"` → `"template"`. +- `pkg/cmd/template_update.go:43, 51, 53-58, 96` — `"name"` → `"template"`. +- `pkg/registry/registry.go:48, 53, 73` — `"name"` → `"template"`. + +### 6. Prompt-source semantics — log final winner only (review #6) + +Current behavior in `template_use.go`: +- Line 96 logs `source="values_file"` for every key in the values file. +- Line 108 logs `source="arg_flag"` for `--arg` keys. +- Line 119 logs `source="default"` for non-provided keys (when `--use-defaults`). +- Lines 254, 259 log `source="prompt"` when the user is prompted. +- `context.go:100` logs `source="computed"` after `ApplyComputed`. + +Problem: a key can pass through `values_file` *and* `arg_flag` (override), or be +prompted after a `values_file` entry was discarded. Today both logs fire. + +Fix: defer the resolution log until **after** the final value is established for +each key. + +- Replace the per-step logs with a single "resolved sources" emission immediately + before `ApplyComputed`. Build a `map[string]string` (key → final source) as + values move through values_file → arg_flag → prompt → default, overwriting + previous entries. Then emit one `slog.Debug("context key resolved", "key", k, "source", finalSource)` per key in alphabetical order. +- `ApplyComputed` continues to log `source="computed"` for its keys (those never + overlap with user-input keys per `extractComputed`'s conflict check). + +### 7. LoadStatus / metadata failure logging consistency (review #5) + +Audit every `LoadMetadata`/`LoadStatus` caller and ensure every error path logs at +debug: +- `pkg/cmd/template_list.go:45, 50` ✓ already logs +- `pkg/cmd/template_update.go:43, 95` ✓ already logs +- `pkg/registry/registry.go:43, 50, 73` ✓ already logs +- `pkg/template/template.go:120` (LoadMetadata inside `Get`) ✓ already logs +- Verify no other callers exist via `Grep "LoadStatus\|LoadMetadata"`. + +Also instrument the two currently-swallowed file mutations: +- `pkg/cmd/template_list.go:101`: `_ = pkgtemplate.SaveStatus(...)` → log on error. +- `pkg/cmd/template_update.go:64`: same. + +### 8. Repo-wide audit of `, _ :=` and `_ = err` (review #9) + +After the targeted fixes above, run a sweep: +- `Grep -n ", _ :=" pkg` and `Grep -n "_ = " pkg` (Go files). +- For each hit, decide: (a) intentional discard, leave alone; (b) diagnostic value, + add `slog.Debug(...)`; (c) actual bug, propagate the error. +- Document any intentional discards with a one-line comment where the reason is non-obvious. + +### 9. Tests (review #7, #8) + +**TestMain pattern** — add `helpers_test.go` files (or extend existing ones) in +every package whose tests trigger logging code paths. Each contains: + +```go +func TestMain(m *testing.M) { + slog.SetDefault(slog.New(slog.NewTextHandler(io.Discard, nil))) + os.Exit(m.Run()) +} +``` + +Packages: `pkg/template`, `pkg/hooks`, `pkg/cmd`, `pkg/registry`, `pkg/util/git`. + +**Remove `discardLogger()`** from `pkg/template/helpers_test.go` and +`pkg/hooks/hooks_test.go` — no longer needed after the signature change. Update +all `Load(...)` / `Get(...)` callers in tests. + +**New tests:** + +- `pkg/template/metadata_test.go` — verify malformed `__metadata.json` produces a + parse error from `LoadMetadata` (already partly tested; ensure the error path + is asserted). +- `pkg/cmd/template_list_test.go` — table-driven test for the `template list` + remote-check path: with a fake `checkRemoteFn` returning each `ErrorKind`, + assert the row's status label and that logging attributes are emitted (capture + via a per-test `slog.SetDefault` swap with `slog.NewTextHandler(&buf, ...)`). +- `pkg/cmd/root_test.go` — assert `--debug --output=json` keeps logs on stderr + (JSON handler) while command data goes to stdout. Run a `template list` against + a registry with one local template; parse stderr as NDJSON and stdout as JSON + table; assert disjoint streams. +- `pkg/cmd/template_use_test.go` — verify the prompt-source dedup: pass + `--values` plus `--arg` for the same key, assert the final log has + `source="arg_flag"` not `source="values_file"`. +- `pkg/util/git` — light coverage for the new git-layer log entries via a + capture handler; assert `repo`, `dest`, `branch` are present in `Clone` entry. + +### 10. Docs update (review #10) + +`docs/content/docs/architecture/overview.md` (the "Logging" section that PR #69 +adds, around the end of the file): + +- Replace the **Flags** description: the slog default is set in + `NewApp()`/`PersistentPreRunE`; remove the obsolete "stored in `App.Logger`" + sentence. +- Update the **Log points** table to match the actually-emitted attributes. + Notably: `pkg/template` `Get` now uses `template` (not `root`); add + `pkg/util/git` rows for `Clone`, `Describe`, `CheckRemoteContext`; add + `pkg/registry` row for `Upgrade`. +- Replace the **Consistent attribute keys** table with the final set from §5. +- Note (under the example) that `slog.SetDefault` is called by `NewApp()` and + re-set in `PersistentPreRunE` when `--debug --output=json` swaps the handler. + +`README.md` — verify nothing user-facing changed. `--debug` and `--output=json` +flag semantics are unchanged; no update expected, but spot-check to confirm. + +## Critical files (final list) + +``` +pkg/cmd/app.go +pkg/cmd/root.go +pkg/cmd/template_use.go +pkg/cmd/template_list.go +pkg/cmd/template_update.go +pkg/cmd/template_download.go +pkg/cmd/use.go +pkg/hooks/hooks.go +pkg/hooks/hooks_test.go +pkg/template/template.go +pkg/template/context.go +pkg/template/context_test.go +pkg/template/functions.go +pkg/template/metadata.go +pkg/template/helpers_test.go +pkg/registry/registry.go +pkg/util/git/git.go +docs/content/docs/architecture/overview.md +``` + +Plus new `helpers_test.go` / `TestMain` files in any package not already covered, +and new test files listed in §9. + +## Reuse map + +Nothing new needs inventing; everything is rewiring existing functions: + +- `slog` package-level `Debug/Info/Warn/Error` (Go stdlib) replaces every + injected-logger call. +- `slog.SetDefault` replaces `App.Logger` mutation. +- `RemoteCheckResult.Err()` (`pkg/util/git/git.go:269`) already exposes typed + errors — keeps callers that want typed errors well-served after the signature + change in §3. +- `output.Writer` (warnings/errors to humans) stays untouched — it serves a + different purpose from `slog` (user-facing UX vs. diagnostic stream). + +## Verification + +1. **Compile & unit tests:** `task test` (per `.github/instructions/executing-commands.md`). +2. **Static analysis:** `task lint` or whatever is configured under + `.github/workflows/` (run via the `ci-green-check` skill at the end). +3. **CLI smoke:** + - `specs --debug template ls 2>&1 1>/dev/null | head -20` — should show + structured debug lines with stable attribute keys; no `root=` should appear. + - `specs --debug --output=json template ls 2>logs.ndjson 1>data.json` — verify + `logs.ndjson` parses line-by-line as JSON with the expected keys; `data.json` + is the table data only. + - `specs --debug template download testtpl 2>&1 | grep "git clone"` — + verify the git-layer log entry fires with `repo`, `dest`, `branch`. + - `specs --debug template use testtpl ./out --arg Name=foo --values vals.json` + where `vals.json` contains `{"Name":"bar"}` — verify only **one** log line + for `key=Name` and it has `source="arg_flag"`. + - `specs --debug template upgrade testtpl` — verify the new `upgrade *` log + points fire. +4. **Test coverage for log-sensitive paths:** confirm the new tests in §9 all + pass, including the capture-handler assertions. +5. **Docs check:** grep `docs/content/docs/architecture/overview.md` for any + attribute key not in the §5 table; should be none.