diff --git a/docs/content/docs/architecture/library-decisions.md b/docs/content/docs/architecture/library-decisions.md index e734d77..f31f874 100644 --- a/docs/content/docs/architecture/library-decisions.md +++ b/docs/content/docs/architecture/library-decisions.md @@ -154,7 +154,8 @@ Backwards compatibility layer is **not** used. - Zero additional dependency. - Structured key-value fields give context to debug messages. -- Silent by default; activated by `--debug` on the root command. +- Silent by default — `output.LevelSilent` sits above every level slog defines, so the silence + holds regardless of what level a new log point uses; activated by `--debug` on the root command. --- diff --git a/docs/content/docs/architecture/output.md b/docs/content/docs/architecture/output.md index b421928..b021e30 100644 --- a/docs/content/docs/architecture/output.md +++ b/docs/content/docs/architecture/output.md @@ -90,7 +90,8 @@ nothing, because the next line rejects it. explanation with `Info`. `slog` is a third channel and not part of this contract: a debug-only diagnostic stream on stderr. -See [Logging](overview#logging). +`SetupLogger` in `log.go` is the only place its handler is built, and its default level is +`LevelSilent`, so nothing reaches a user who did not ask for it. See [Logging](overview#logging). --- diff --git a/docs/content/docs/architecture/overview.md b/docs/content/docs/architecture/overview.md index 2eb3bc3..e56fd8b 100644 --- a/docs/content/docs/architecture/overview.md +++ b/docs/content/docs/architecture/overview.md @@ -29,7 +29,7 @@ specs-cli/ │ └── errors.go # sentinel errors ├── cmd/ # one file per Cobra command │ ├── root.go - │ ├── app.go # App struct, --debug/--safe-mode flags + │ ├── app.go # App struct, shared dependencies │ ├── use.go # specs use │ ├── template.go # specs template subcommand group │ ├── template_download.go @@ -63,7 +63,7 @@ specs-cli/ ├── exit/ # exit codes ├── git/ # go-git wrapper, SSH auth, remote check ├── osutil/ # file operations (CopyDir, etc.) - ├── output/ # lipgloss-based logger + table renderer + ├── output/ # Writer implementations, table renderer, slog setup ├── validate/ # Name() validator and argument validators └── values/ # --values file (JSON/YAML) + --arg flag parsing ``` @@ -286,20 +286,36 @@ See [Output](output) for the full contract, the colour and width decisions and t `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. +logger. -`slog` is a **debug-only diagnostic channel** on **stderr** — it is silent on a normal run (every -log point is `Debug`, suppressed at the default `Info` level) and is distinct from the two -`output.Writer` formats (`pretty`/`json`) that produce user-facing output on stdout. Do not use -`slog` for user-facing reporting; use `output.Writer`. +`slog` is a **debug-only diagnostic channel** on **stderr** — silent on a normal run, and distinct +from the two `output.Writer` formats (`pretty`/`json`) that produce user-facing output on stdout. +Do not use `slog` for user-facing reporting; use `output.Writer`. + +That silence is **enforced, not conventional**. `output.LevelSilent` is `slog.LevelError + 1`, above +every level slog defines, and it is the level a run without `--debug` gets — so a `slog.Info` or +`slog.Warn` added anywhere in the tree still writes nothing. It does not depend on every log point +happening to be `Debug`. + +### One constructor, called twice + +`output.SetupLogger(w io.Writer, format Format, debug bool) *slog.LevelVar` is the only place a +handler is built. It installs the process-wide default and returns the `LevelVar` gating it: + +| Caller | Stream | Why | +|---------------------|---------------------|------------------------------------------------------------------------------------------------------------------------------| +| `NewApp()` | `os.Stderr` | Cobra parses persistent flags only after the tree is built, so a failure before that still needs a logger. Silent, `pretty`. | +| `PersistentPreRunE` | `cmd.ErrOrStderr()` | The flags are now resolved. Writing to the command's own stderr is what lets a test assert on `--debug` output. | ### 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 | +| Flag | Effect | +|-----------------------------|--------------------------------------------------------------------------------| +| *(neither)* | Level `LevelSilent` — nothing is emitted at any level | +| `--debug` | Level `Debug`, text records on stderr | +| `--debug` + `--output=json` | Level `Debug`, JSON records on stderr, so that stream is JSON all the way down | + +`--output` alone does not change logging: without `--debug` there is nothing to format. ### Log points @@ -345,8 +361,7 @@ 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. +the **log** format on stderr. The two streams are independent. --- diff --git a/internal/cmd/app.go b/internal/cmd/app.go index 746ff76..5b5cbfc 100644 --- a/internal/cmd/app.go +++ b/internal/cmd/app.go @@ -2,7 +2,6 @@ package cmd import ( "context" - "log/slog" "os" "time" @@ -11,45 +10,9 @@ import ( "github.com/specsnl/specs-cli/internal/util/output" ) -// HandlerFactory creates a slog.Handler wired to the given LevelVar. -// The LevelVar is passed so that WithDebug can adjust the level at runtime -// regardless of which handler is in use. -type HandlerFactory func(level *slog.LevelVar) slog.Handler - -// Option is a functional option for configuring an App. -type Option func(*App) - -// WithDebug returns an Option that sets the log level to debug when enabled, -// or back to info when false. -func WithDebug(enabled bool) Option { - return func(a *App) { - if enabled { - a.level.Set(slog.LevelDebug) - } else { - a.level.Set(slog.LevelInfo) - } - } -} - -// 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: -// -// app := NewApp(WithHandler(func(level *slog.LevelVar) slog.Handler { -// return slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{Level: level}) -// })) -func WithHandler(factory HandlerFactory) Option { - return func(a *App) { - slog.SetDefault(slog.New(factory(a.level))) - } -} - // App holds application-wide dependencies shared across all commands. type App struct { Output output.Writer - level *slog.LevelVar SafeMode bool HookEnvPrefix string // prefix for context keys injected as env vars into hooks @@ -62,29 +25,22 @@ type App struct { refreshTimeout time.Duration } -// 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{ +// NewApp creates an App. +// +// The logger it installs is silent: nothing is emitted until PersistentPreRunE +// calls output.SetupLogger again with the resolved --debug and --output flags. +// This first call exists only so that a failure before flag parsing has a +// default logger to reach, and it writes to os.Stderr because no command — and +// therefore no cmd.ErrOrStderr() — exists yet. +func NewApp() *App { + output.SetupLogger(os.Stderr, output.FormatPretty, false) + + return &App{ Output: output.NewDefaultPrettyWriter(), - level: level, checkRemoteFn: pkggit.CheckRemoteContext, checkTimeout: 10 * time.Second, refreshTimeout: 30 * time.Second, } - - for _, opt := range opts { - opt(app) - } - - return app } // templateConfig translates App-level flags into a template.Config. diff --git a/internal/cmd/root.go b/internal/cmd/root.go index 077c3ce..2e97d49 100644 --- a/internal/cmd/root.go +++ b/internal/cmd/root.go @@ -3,7 +3,6 @@ package cmd import ( "context" "fmt" - "log/slog" "github.com/spf13/cobra" @@ -60,17 +59,10 @@ Use "specs --help" for more information about a command.`, outputFlag, output.FormatPretty, output.FormatJSON) } - // Configure the slog logger level; swap to JSON handler when both - // --debug and --output=json are set. - if debug { - app.level.Set(slog.LevelDebug) - - if format == output.FormatJSON { - slog.SetDefault(slog.New(slog.NewJSONHandler(cmd.ErrOrStderr(), &slog.HandlerOptions{Level: app.level}))) - } - } else { - app.level.Set(slog.LevelInfo) - } + // Re-install the logger now the flags are known: on the command's own + // stderr, so a test can read what --debug wrote, and in the format + // --output selected. Without --debug it is silent. + output.SetupLogger(cmd.ErrOrStderr(), format, debug) return nil }, diff --git a/internal/cmd/root_test.go b/internal/cmd/root_test.go index 2f0cf1f..a97c12c 100644 --- a/internal/cmd/root_test.go +++ b/internal/cmd/root_test.go @@ -3,6 +3,7 @@ package cmd import ( "bytes" "fmt" + "log/slog" "strings" "testing" @@ -45,6 +46,25 @@ func executeCmdStreams(args ...string) (stdout, stderr string, err error) { return out.String(), errOut.String(), err } +// executeCmdStreamsWith runs the command and then calls emit, which stands in +// for a log point somewhere in the tree. It runs after Execute rather than +// during it because the logger PersistentPreRunE installed is process-wide and +// still in place — so whatever emit writes lands wherever a real log point +// would have, without needing a command that happens to log. +func executeCmdStreamsWith(emit func(), args ...string) (stdout, stderr string, err error) { + app := NewApp() + cmd := newRootCmd(app) + out, errOut := new(bytes.Buffer), new(bytes.Buffer) + cmd.SetOut(out) + cmd.SetErr(errOut) + cmd.SetArgs(args) + err = cmd.Execute() + + emit() + + return out.String(), errOut.String(), err +} + func TestHelp_ExitsZero(t *testing.T) { out, err := executeCmd("--help") if err != nil { @@ -108,6 +128,65 @@ func TestOutputFlag_InvalidIsRejected(t *testing.T) { } } +// The logger PersistentPreRunE installs writes to the command's own stderr, so +// a test can read what --debug produced instead of it escaping to os.Stderr. +func TestDebugFlag_Logging(t *testing.T) { + tests := []struct { + name string + args []string + assert func(t *testing.T, stderr string) + }{ + { + name: "silent without --debug", + args: []string{"version"}, + assert: func(t *testing.T, stderr string) { + t.Helper() + + if strings.Contains(stderr, "level=") || strings.Contains(stderr, `"level":"DEBUG"`) { + t.Errorf("stderr = %q, want no log records without --debug", stderr) + } + }, + }, + { + name: "--debug emits text records", + args: []string{"--debug", "version"}, + assert: func(t *testing.T, stderr string) { + t.Helper() + + if !strings.Contains(stderr, "level=DEBUG") { + t.Errorf("stderr = %q, want a text record", stderr) + } + }, + }, + { + name: "--debug -o json emits JSON records", + args: []string{"--debug", "-o", "json", "version"}, + assert: func(t *testing.T, stderr string) { + t.Helper() + + if !strings.Contains(stderr, `"level":"DEBUG"`) { + t.Errorf("stderr = %q, want a JSON record", stderr) + } + }, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + previous := slog.Default() + + t.Cleanup(func() { slog.SetDefault(previous) }) + + _, stderr, err := executeCmdStreamsWith(func() { slog.Debug("a diagnostic") }, tt.args...) + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + + tt.assert(t, stderr) + }) + } +} + func TestHookEnvPrefix_Default(t *testing.T) { app, _, err := executeCmdWithApp("version") if err != nil { diff --git a/internal/cmd/template_validate.go b/internal/cmd/template_validate.go index b0ddf3a..cf59abd 100644 --- a/internal/cmd/template_validate.go +++ b/internal/cmd/template_validate.go @@ -3,7 +3,6 @@ package cmd import ( "errors" "fmt" - "log/slog" "os" "path/filepath" @@ -21,8 +20,6 @@ func newTemplateValidateCmd(app *App) *cobra.Command { Short: "Validate a template directory", Args: cobra.ExactArgs(1), RunE: func(cmd *cobra.Command, args []string) error { - app.level.Set(slog.LevelDebug) - templateRoot := args[0] templateDir := filepath.Join(templateRoot, specs.TemplateDirFile) diff --git a/internal/util/output/log.go b/internal/util/output/log.go index ad89311..5bc0861 100644 --- a/internal/util/output/log.go +++ b/internal/util/output/log.go @@ -1 +1,51 @@ package output + +import ( + "io" + "log/slog" +) + +// LevelSilent is above every level slog defines, so a logger set to it emits +// nothing at all — not even slog.Error. +// +// It is the default because slog is a diagnostic channel for someone debugging +// specs, not a reporting channel for someone using it: everything a user should +// see goes through Writer. Making silence the level rather than a convention is +// what keeps that true when the first slog.Info is added to the tree. +const LevelSilent = slog.LevelError + 1 + +// SetupLogger installs the process-wide default slog logger on w and returns the +// LevelVar gating it. debug selects slog.LevelDebug; otherwise the level is +// LevelSilent and nothing is written. The handler matches format, so +// `--debug -o json` yields a stderr stream that is JSON all the way down. +// +// The level is returned rather than baked in because cobra parses persistent +// flags only after the command tree is built: NewApp calls this with a silent +// default so a failure before flag parsing still has somewhere to go, and +// PersistentPreRunE calls it again with the command's own stderr and the +// resolved flags. +func SetupLogger(w io.Writer, format Format, debug bool) *slog.LevelVar { + level := new(slog.LevelVar) + if debug { + level.Set(slog.LevelDebug) + } else { + level.Set(LevelSilent) + } + + slog.SetDefault(slog.New(newHandler(w, format, level))) + + return level +} + +// newHandler builds the handler for a format: JSON records for FormatJSON, text +// for everything else. An unrecognised format still has to log somewhere, and +// text is what a human reading a terminal wants. +func newHandler(w io.Writer, format Format, level slog.Leveler) slog.Handler { + opts := &slog.HandlerOptions{Level: level} + + if format == FormatJSON { + return slog.NewJSONHandler(w, opts) + } + + return slog.NewTextHandler(w, opts) +} diff --git a/internal/util/output/log_test.go b/internal/util/output/log_test.go new file mode 100644 index 0000000..2d82d50 --- /dev/null +++ b/internal/util/output/log_test.go @@ -0,0 +1,99 @@ +package output_test + +import ( + "bytes" + "encoding/json" + "log/slog" + "strings" + "testing" + + "github.com/specsnl/specs-cli/internal/util/output" +) + +// restoreLogger puts the process-wide default logger back after a test has +// replaced it, so one case cannot leak its handler into the next. +func restoreLogger(t *testing.T) { + t.Helper() + + previous := slog.Default() + + t.Cleanup(func() { slog.SetDefault(previous) }) +} + +// Silence is the level, not a convention: every level slog defines is below +// LevelSilent, so the first slog.Info someone adds to the tree still writes +// nothing on a run without --debug. +func TestSetupLogger_SilentWithoutDebug(t *testing.T) { + restoreLogger(t) + + var buf bytes.Buffer + + output.SetupLogger(&buf, output.FormatPretty, false) + + slog.Debug("debug record") + slog.Info("info record") + slog.Warn("warn record") + slog.Error("error record") + + if buf.Len() != 0 { + t.Errorf("logged %q without --debug, want nothing", buf.String()) + } +} + +func TestSetupLogger_DebugWritesToTheGivenStream(t *testing.T) { + restoreLogger(t) + + var buf bytes.Buffer + + output.SetupLogger(&buf, output.FormatPretty, true) + + slog.Debug("debug record", "key", "value") + + got := buf.String() + if !strings.Contains(got, "debug record") || !strings.Contains(got, "key=value") { + t.Errorf("logged %q, want a text record carrying the message and its attribute", got) + } +} + +func TestSetupLogger_DebugJSONEmitsJSONRecords(t *testing.T) { + restoreLogger(t) + + var buf bytes.Buffer + + output.SetupLogger(&buf, output.FormatJSON, true) + + slog.Debug("debug record", "key", "value") + + var record map[string]any + if err := json.Unmarshal(buf.Bytes(), &record); err != nil { + t.Fatalf("unmarshal %q: %v", buf.String(), err) + } + + if got, want := record["msg"], "debug record"; got != want { + t.Errorf("msg = %v, want %v", got, want) + } + + if got, want := record["key"], "value"; got != want { + t.Errorf("key = %v, want %v", got, want) + } +} + +// The returned LevelVar is the handle on the installed logger, so a caller that +// resolves --debug later can raise the level without rebuilding the handler. +func TestSetupLogger_ReturnsTheGatingLevel(t *testing.T) { + restoreLogger(t) + + var buf bytes.Buffer + + level := output.SetupLogger(&buf, output.FormatPretty, false) + if got := level.Level(); got != output.LevelSilent { + t.Errorf("level = %v, want %v", got, output.LevelSilent) + } + + level.Set(slog.LevelDebug) + slog.Debug("now visible") + + if !strings.Contains(buf.String(), "now visible") { + t.Errorf("logged %q, want the record after raising the returned level", buf.String()) + } +}