diff --git a/docs/services/logging.md b/docs/services/logging.md index 2d085b0d..37bb3bd8 100644 --- a/docs/services/logging.md +++ b/docs/services/logging.md @@ -8,7 +8,7 @@ order: 105 SummerCMS logs through the standard library's `log/slog`, configured by [diary](../../modules/diary/README.md). Where a WinterCMS application lists channels in `config/logging.php` and calls `Log::error`, a SummerCMS application lists channels in `config/log.yaml` and logs through a component logger from `diary.For`. Every channel redacts credentials through [sunscreen](../../modules/sunscreen/README.md). -The application `main` that `summer build` generates calls `diary.Bootstrap(os.Stderr, diary.Options{})` as the first statement of `run`, so even configuration errors are logged, and `diary.Setup` right after `compass` has loaded `config/`. From then on component loggers, `slog.Default`, the package-level `slog` functions and the standard `log` package all write through the configured channels. +The application `main` that `summer build` generates calls `diary.Bootstrap(os.Stderr, diary.FromGlobals(g))` first, with the global options it read from the command line, so even configuration errors are logged, and `diary.Setup` with the same options right after `compass` has loaded `config/`. An invocation that only asks for help (`serve --help`) boots with the console at warnings unless `-v` is given, so the info lines plugins log while they register and boot do not print above the help. From then on component loggers, `slog.Default`, the package-level `slog` functions and the standard `log` package all write through the configured channels. ## Channels diff --git a/modules/diary/README.md b/modules/diary/README.md index 9008681d..332ca47a 100644 --- a/modules/diary/README.md +++ b/modules/diary/README.md @@ -10,7 +10,7 @@ Application logging modelled on Laravel's logging config: named channels (consol `diary` owns the process logger of a SummerCMS application. `config/log.yaml` names a default channel, a global level and a map of channels, the way Laravel's `config/logging.php` does: a console channel that prints styled lines on a terminal, daily files with retention, and a stack that fans a record out to several channels. Code logs through named component loggers (`diary.For`), so every record carries the plugin or module it came from. Every channel is wrapped by `sunscreen.Wrap`, so credentials are redacted whichever channel a record reaches. -The application `main` that `summer build` generates reads the console global options first (`bonfire.PeekGlobals`), calls `diary.Bootstrap` with them, which installs a console channel before configuration is read, and `diary.Setup` right after `compass` loads `config/`. Once the command line is parsed, `diary.ApplyGlobals` re-applies `-v`, `-q` and `--ansi`/`--no-ansi`. +The application `main` that `summer build` generates reads the console global options first (`bonfire.PeekGlobals`), calls `diary.Bootstrap` with them, which installs a console channel before configuration is read, and `diary.Setup` right after `compass` loads `config/`. `diary.FromGlobals` also records the process arguments, and `diary.Bootstrap` and `diary.Setup` start the console at warnings for an invocation that only asks for help (`serve --help`), unless `-v` is given, so the info lines plugins log while they register and boot do not print above the help. Once the command line is parsed, `diary.ApplyGlobals` re-applies `-v`, `-q` and `--ansi`/`--no-ansi`. ## Role in the framework @@ -34,6 +34,7 @@ Use cases: - Redaction: every channel leaf is wrapped by `sunscreen.Wrap`. - Runtime verbosity: `diary.SetVerbosity` lets info (1) or debug (2) through for every component and adds source locations on styled lines (3); quiet raises only the console channels to warn. - Console global options: `diary.FromGlobals` turns `-v`/`-vv`/`-vvv`, `-q` and `--ansi`/`--no-ansi` into `diary.Options`, and `diary.ApplyGlobals` applies them to the running setup (the generated main registers it with `bonfire.OnGlobals`). +- Quiet boot for help: `diary.FromGlobals` also records the process arguments (`os.Args[1:]`) in `diary.Options`, and `diary.Bootstrap` and `diary.Setup` start the console channels at warnings, as `-q` would, when those arguments only ask for help (`-h` or `--help`) and no `-v` is given. Daily files and stderr channels keep their levels, warnings and errors still print, and an existing generated main gets it from a framework upgrade alone. A `diary.Options` literal without arguments does no check. - The process default logger (`slog.Default`) and the standard `log` package log through the configured channels without a component. ## Usage @@ -86,13 +87,13 @@ Tests that set diary up restore the previous process logger with `t.Cleanup(diar | `diary.Bootstrap` | Installs a console channel on a writer before configuration is read and makes diary the process default logger. | | `diary.Setup` | Parses `log.*` from a `compass` configuration, builds the channels and installs them; returns configuration errors. | | `diary.SetVerbosity` | Changes verbosity and quiet at runtime. | -| `diary.FromGlobals` | Returns the `diary.Options` (verbosity, quiet, color mode) of the console global options in a `bonfire.Globals`. | +| `diary.FromGlobals` | Returns the `diary.Options` (verbosity, quiet, color mode) of the console global options in a `bonfire.Globals`, with the process arguments (`os.Args[1:]`) in `Args`. | | `diary.ApplyGlobals` | Applies parsed `bonfire.Globals` to the running setup: verbosity and quiet, and the console color mode when it changed. | | `diary.Verbosity` | Returns the current verbosity. | | `diary.HideOnTTY` | Marks a context so a console channel writing to a terminal skips the records logged with it; files, stderr channels and a console that is not a terminal (also one with forced color, `--ansi` or `FORCE_COLOR`) still write them. Used for facts a command has just printed as a block, such as `serve`'s startup summary. | | `diary.Reset` | Drops the setup, closes its files and restores the process default logger captured at the first setup. | | `diary.Close` | Closes the open daily files; later records open them again. | -| `diary.Options` | Setup options: `Verbosity`, `Quiet`, `Color`, `Root`, `Stderr`, `Environ` and `Now`. | +| `diary.Options` | Setup options: `Verbosity`, `Quiet`, `Color`, `Root`, `Stderr`, `Environ`, `Now` and `Args` (the command-line arguments; when set, an invocation that only asks for help boots with the console at warnings). | | `diary.ParseConfig` | Reads `log.*` over `diary.DefaultConfig`. | | `diary.DefaultConfig` | The framework defaults. | | `diary.Config` | Parsed configuration: `Default`, `Level`, `Channels` and `Components`. | @@ -157,4 +158,4 @@ Environment variables use the `SUMMER_LOG__` prefix with a double underscore bet go test ./modules/diary/... ``` -`TestDiaryTracerSmoke` loads a `config/log.yaml` through `compass`, logs one record from a component logger and checks that it reaches the console and the daily file redacted. `TestConfigEnvSmoke` parses `SUMMER_LOG__` overrides given as strings and checks that every invalid value fails with an error naming its key. `TestDailyDegradesSmoke` points the daily channel at a read-only directory and checks that it warns once and the console keeps logging. The tests write to temporary directories and need no external services. +`TestDiaryTracerSmoke` loads a `config/log.yaml` through `compass`, logs one record from a component logger and checks that it reaches the console and the daily file redacted. `TestConfigEnvSmoke` parses `SUMMER_LOG__` overrides given as strings and checks that every invalid value fails with an error naming its key. `TestDailyDegradesSmoke` points the daily channel at a read-only directory and checks that it warns once and the console keeps logging. `TestBootQuietSmoke` runs the generated main's sequence with a plugin that logs while it registers and boots, and checks that `serve --help` keeps its info lines off the console (but not its warning, nor the daily file) while `serve` prints them. The tests write to temporary directories and need no external services. diff --git a/modules/diary/bootquiet_smoke_test.go b/modules/diary/bootquiet_smoke_test.go new file mode 100644 index 00000000..a7f4f2fc --- /dev/null +++ b/modules/diary/bootquiet_smoke_test.go @@ -0,0 +1,191 @@ +package diary_test + +import ( + "bytes" + "context" + "log/slog" + "os" + "path/filepath" + "slices" + "strings" + "testing" + "time" + + "git.golem15.com/golem15/summercms/modules/backpack" + "git.golem15.com/golem15/summercms/modules/bonfire" + "git.golem15.com/golem15/summercms/modules/compass" + "git.golem15.com/golem15/summercms/modules/diary" + "git.golem15.com/golem15/summercms/modules/party" +) + +// The records the boot-logging test plugin writes. +const ( + bootRegisterInfo = "operators registered" + bootBootInfo = "registries collected" + bootBootWarn = "registry without operators" +) + +// bootLogPlugin logs from Register through slog.Default, the way a plugin +// written before diary does, and from Boot through a component logger. +type bootLogPlugin struct{} + +func (bootLogPlugin) ID() string { return "acme.bootlog" } +func (bootLogPlugin) Requires() []string { return nil } + +func (bootLogPlugin) Register(*backpack.App) error { + slog.Default().Info(bootRegisterInfo, "count", 2) + return nil +} + +func (bootLogPlugin) Boot(*backpack.App) error { + log := diary.For("bootlog") + log.Info(bootBootInfo, "count", 3) + log.Warn(bootBootWarn, "registry", "refunds") + return nil +} + +func init() { + party.Register(bootLogPlugin{}) +} + +// bootLogYAML is a console plus a daily file at info, as in the tracer test. +const bootLogYAML = `default: stack +level: info +channels: + stack: + driver: stack + channels: [console, daily] + console: + driver: console + format: auto + daily: + driver: daily + path: storage/logs/summer.log + days: 14 + format: json + level: info +` + +// TestBootQuietSmoke runs the generated main's sequence (PeekGlobals, +// Bootstrap and Setup with FromGlobals, party.Activate, a root with +// OnGlobals(diary.ApplyGlobals), Execute) with a plugin that logs while it +// registers and boots: an invocation that only asks for help keeps the boot +// Info records off the console, every other one prints them, and the daily +// file and the console's warnings are never affected. +func TestBootQuietSmoke(t *testing.T) { + rows := []struct { + name string + args []string + literal bool // Options as a struct literal, without Args + wantInfo bool // the boot Info records reach the console + }{ + {name: "serve --help", args: []string{"serve", "--help"}}, + {name: "serve", args: []string{"serve"}, wantInfo: true}, + {name: "literal options", args: []string{"serve", "--help"}, literal: true, wantInfo: true}, + } + for _, row := range rows { + t.Run(row.name, func(t *testing.T) { + t.Cleanup(diary.Reset) + root := t.TempDir() + configDir := filepath.Join(root, "config") + if err := os.MkdirAll(configDir, 0o755); err != nil { + t.Fatal(err) + } + if err := os.WriteFile(filepath.Join(configDir, "log.yaml"), []byte(bootLogYAML), 0o644); err != nil { + t.Fatal(err) + } + var console, stdout, stderr bytes.Buffer + now := func() time.Time { return time.Date(2026, 10, 28, 12, 0, 0, 0, time.Local) } + + g := bonfire.PeekGlobals(row.args) + var opts diary.Options + if row.literal { + opts = diary.Options{Verbosity: g.Verbosity, Quiet: g.Quiet, Color: g.Color} + } else { + opts = diary.FromGlobals(g) + opts.Args = slices.Clone(row.args) + if opts.Args == nil { + opts.Args = []string{} + } + } + opts.Root, opts.Stderr, opts.Environ, opts.Now = root, &console, []string{}, now + + diary.Bootstrap(&console, opts) + cfg, err := compass.Open(compass.Options{Dir: configDir, Env: g.Env, Environ: []string{}}) + if err != nil { + t.Fatal(err) + } + if err := diary.Setup(cfg, opts); err != nil { + t.Fatalf("Setup: %v", err) + } + app := backpack.New(cfg) + if _, err := party.Activate(app, []string{"acme.bootlog"}); err != nil { + t.Fatalf("Activate: %v", err) + } + commands := []bonfire.Command{ + {Name: "serve", Description: "Start the HTTP server", Run: func(context.Context, bonfire.Input, bonfire.Output) error { return nil }}, + {Name: "queue:work", Description: "Run the job workers", Run: func(context.Context, bonfire.Input, bonfire.Output) error { return nil }}, + } + rootCmd, err := bonfire.NewRootIO("acme", commands, strings.NewReader(""), &stdout, &stderr, + bonfire.WithVersion(bonfire.Version{App: "v1.0.0", Framework: "v1.0.0"}), bonfire.OnGlobals(diary.ApplyGlobals)) + if err != nil { + t.Fatal(err) + } + if code := bonfire.Execute(context.Background(), rootCmd, row.args); code != bonfire.ExitOK { + t.Fatalf("Execute(%q) = %d, want 0; stderr:\n%s", row.args, code, stderr.String()) + } + if slices.Contains(row.args, "--help") && !strings.Contains(stdout.String(), "serve") { + t.Errorf("Execute(%q) printed no help:\n%s", row.args, stdout.String()) + } + + out := console.String() + for _, msg := range []string{bootRegisterInfo, bootBootInfo} { + if got := strings.Contains(out, msg); got != row.wantInfo { + t.Errorf("console holds %q = %v, want %v:\n%s", msg, got, row.wantInfo, out) + } + } + if !strings.Contains(out, bootBootWarn) { + t.Errorf("console lacks the boot warning %q:\n%s", bootBootWarn, out) + } + + if err := diary.Close(); err != nil { + t.Fatalf("Close: %v", err) + } + files, err := filepath.Glob(filepath.Join(root, "storage", "logs", "*.log")) + if err != nil || len(files) != 1 { + t.Fatalf("daily files = %v (%v), want one", files, err) + } + raw, err := os.ReadFile(files[0]) + if err != nil { + t.Fatal(err) + } + for _, msg := range []string{bootRegisterInfo, bootBootInfo, bootBootWarn} { + if !bytes.Contains(raw, []byte(msg)) { + t.Errorf("daily file lacks %q:\n%s", msg, raw) + } + } + }) + } +} + +// TestFromGlobalsArgs: FromGlobals records a copy of the process arguments +// without the program name, never nil. +func TestFromGlobalsArgs(t *testing.T) { + saved := os.Args + t.Cleanup(func() { os.Args = saved }) + + os.Args = []string{"acme", "serve", "--help"} + opts := diary.FromGlobals(bonfire.Globals{}) + if want := []string{"serve", "--help"}; !slices.Equal(opts.Args, want) { + t.Fatalf("Args = %q, want %q", opts.Args, want) + } + opts.Args[0] = "migrate" + if os.Args[1] != "serve" { + t.Errorf("changing Args changed os.Args to %q", os.Args) + } + + os.Args = []string{"acme"} + if opts := diary.FromGlobals(bonfire.Globals{}); opts.Args == nil || len(opts.Args) != 0 { + t.Errorf("Args = %#v, want an empty non-nil slice", opts.Args) + } +} diff --git a/modules/diary/diary.go b/modules/diary/diary.go index eb33bf72..3cc30bad 100644 --- a/modules/diary/diary.go +++ b/modules/diary/diary.go @@ -31,6 +31,8 @@ type Options struct { // to debug; 3 or more also adds source locations on the console. Verbosity int // Quiet raises the console channels to warn; files keep their levels. + // Bootstrap and Setup also set it for arguments that only ask for help + // (see Args). Quiet bool // Color decides on styled console output (bonfire.ColorAuto by default). Color consolekit.ColorMode @@ -43,6 +45,14 @@ type Options struct { Environ []string // Now is the clock of the daily writers; nil means time.Now. Now func() time.Time + // Args are the command-line arguments without the program name. When + // non-nil, Bootstrap and Setup check whether they only ask for help + // and, at verbosity 0, install the setup with Quiet, so the records + // plugins log while they register and boot stay off the console. + // FromGlobals sets them to a copy of os.Args[1:]; nil (an Options + // literal) means no check. A caller that dispatches on other arguments + // sets Args itself. + Args []string } func (o Options) normalize() Options { @@ -116,13 +126,15 @@ func For(component string) *slog.Logger { // Bootstrap installs a console channel on w, before configuration is read, // and makes diary the process default logger. The generated main calls it -// first; Setup replaces it once config/log.yaml is loaded. +// first; Setup replaces it once config/log.yaml is loaded. Like Setup, it +// starts the console at warn when opts.Args only ask for help and no -v is +// given. func Bootstrap(w io.Writer, opts Options) { if w == nil { w = os.Stderr } opts.Stderr = w - opts = opts.normalize() + opts = bootQuiet(opts.normalize()) cfg := DefaultConfig() cfg.Default = "console" cfg.Channels = map[string]ChannelConfig{"console": {Driver: DriverConsole, Format: FormatAuto}} @@ -138,13 +150,14 @@ func Bootstrap(w io.Writer, opts Options) { // Setup parses log.* from cfg (ParseConfig), builds the channels and makes // them the target of every diary logger and of the process default logger. // A configuration error is returned and leaves the previous setup in place; -// a daily file that cannot be opened never fails Setup. +// a daily file that cannot be opened never fails Setup. When opts.Args only +// ask for help and no -v is given, the console channels start at warn. func Setup(cfg *compass.Config, opts Options) error { conf, err := ParseConfig(cfg) if err != nil { return err } - opts = opts.normalize() + opts = bootQuiet(opts.normalize()) ch, err := buildChannels(conf, opts) if err != nil { return err @@ -215,9 +228,15 @@ func setVerbosityLocked(v int, quiet bool) { // FromGlobals returns the Options for the console global options: their // verbosity, quiet switch and color mode. The generated main passes it to // Bootstrap and Setup. g is a bonfire.Globals: bonfire and diary share the -// type through internal/consolekit, so diary does not link bonfire. +// type through internal/consolekit, so diary does not link bonfire. It also +// sets Args to a copy of os.Args[1:] (empty, not nil, without arguments), so +// an invocation that only asks for help boots with the console at warn. func FromGlobals(g consolekit.Globals) Options { - return Options{Verbosity: g.Verbosity, Quiet: g.Quiet, Color: g.Color} + args := []string{} + if len(os.Args) > 1 { + args = append(args, os.Args[1:]...) + } + return Options{Verbosity: g.Verbosity, Quiet: g.Quiet, Color: g.Color, Args: args} } // ApplyGlobals applies the parsed global options to the installed setup: diff --git a/modules/diary/helponly.go b/modules/diary/helponly.go new file mode 100644 index 00000000..f5472d6d --- /dev/null +++ b/modules/diary/helponly.go @@ -0,0 +1,55 @@ +package diary + +// helpOnly reports whether args, a binary's command line without the +// program name, only ask for help: before "--" they hold --help or a +// single-dash cluster that reaches h. It is a tolerant pre-scan of the raw +// arguments, made before plugins boot, and reads them the way +// bonfire.PeekGlobals does: it stops at "--", skips the value of --env and +// reads a single-dash cluster letter by letter, stopping at the first +// letter that is not a global shorthand (v, q, n, h). It never fails and +// cannot tell a passthrough command (whose --help reaches its Run) from +// another, so " --help" counts; the root's OnGlobals hook +// (ApplyGlobals) restores the console levels before that command runs. +func helpOnly(args []string) bool { + for i := 0; i < len(args); i++ { + a := args[i] + switch { + case a == "--": + return false + case a == "--env": + i++ + case a == "--help": + return true + case len(a) >= 2 && a[0] == '-' && a[1] != '-': + if clusterHasHelp(a[1:]) { + return true + } + } + } + return false +} + +// clusterHasHelp reports whether a shorthand cluster (the letters after the +// dash) reaches h before a letter that is not a global shorthand. +func clusterHasHelp(cluster string) bool { + for i := 0; i < len(cluster); i++ { + switch cluster[i] { + case 'h': + return true + case 'v', 'q', 'n': + default: + return false + } + } + return false +} + +// bootQuiet applies the help-only rule of Bootstrap and Setup: with Args +// set, no -v and arguments that only ask for help, the setup is installed +// with Quiet, which raises only the console channels to warn. +func bootQuiet(opts Options) Options { + if opts.Args != nil && opts.Verbosity == 0 && helpOnly(opts.Args) { + opts.Quiet = true + } + return opts +}