#51: feat: improve observability via structured logging

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
 ```
 
 ---

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,36 +42,37 @@ 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
 	HookEnvPrefix string // prefix for context keys injected as env vars into hooks
 
 	// 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)
-}

pkg/cmd/root.go

@@ -56,7 +56,7 @@ Use "specs <command> --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)

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

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"
 }
-

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()

pkg/cmd/template_update.go

@@ -1,6 +1,7 @@
 package cmd
 
 import (
+	"log/slog"
 	"os"
 	"time"
 
@@ -40,20 +41,26 @@ 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()},
 					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)
+				}
 
 				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)