diff --git a/cmd/specsrht/main.go b/cmd/specsrht/main.go index de57cc505efaa4879dff226368d4f313219be230..cd46b92445598f3323bf8172eae9cada76f17043 100644 --- a/cmd/specsrht/main.go +++ b/cmd/specsrht/main.go @@ -45,7 +45,11 @@ // // Parsed by core-go's server.New: // // -b addr bind address (repeatable); default localhost:5091 -// -d debug (verbose request logging in core-go) +// -d debug: verbose request logging in core-go, and — read straight out +// of the argument vector by sr-ht-ecore's logging.Defaults, before +// server.New parses anything — debug verbosity for this daemon's own +// logger from its first line. $LOG_LEVEL does the same for one run, +// and [spec.sr.ht] log-level is the instance's persistent setting. // -m addr Prometheus metrics bind (default random port) // -p addr pprof bind (default random localhost port) // @@ -83,6 +87,7 @@ chimw "github.com/go-chi/chi/v5/middleware" _ "github.com/lib/pq" // registers the "postgres" database/sql driver "github.com/vaughan0/go-ini" "go.bigb.es/auxilia/scribe" + "sourcecraft.dev/bigbes/sr-ht-ecore/logging" "sourcecraft.dev/bigbes/sr-ht-core/auth" "sourcecraft.dev/bigbes/sr-ht-core/config" @@ -127,8 +132,13 @@ if _, _, isHook := hooks.ModeFromArgs(os.Args); isHook { os.Exit(hooks.Run(hooks.Runtime{Args: os.Args})) } - log := newLogger() - slog.SetDefault(log) + // The config is read before the logger so that [spec.sr.ht] log-level is in + // force for the first line this process writes. It cannot fail: core-go's + // LoadConfig answers a nil ini.File for an instance with no config file at + // all, and validateConfig — which runs later, in run — is what turns that + // into one message an operator can act on. + conf := config.LoadConfig() + log := installLogger(conf) // Admin subcommands run and exit without binding anything, so they are safe // to invoke while the daemon holds the hook socket. @@ -146,7 +156,7 @@ return } } - if err := run(log); err != nil { + if err := run(conf, log); err != nil { // Plain text, not a log record. A startup failure is read by a human // on a terminal, and the configuration report is deliberately several // lines long — a structured handler would escape it into one. @@ -230,65 +240,47 @@ return fmt.Errorf("unknown subcommand %q: want create or list", args[0]) } } -// newLogger builds the process logger. LOG_LEVEL raises or lowers verbosity; -// everything goes to stderr, because a hook's stdout is forwarded to the -// pushing client and this binary is both programs. +// installLogger builds the process logger and makes it slog's default. // -// It is the whole logging configuration of this service, and it is installed -// with slog.SetDefault rather than threaded everywhere. That is what makes the -// library packages loggable at all: the read plane, the credential resolver and -// sr-ht-ecore's panic middleware all log through the default logger, and none -// of them takes a *slog.Logger — a middleware in another module cannot be -// handed this one, and without the SetDefault its panic reports would come out -// of Go's plain stderr handler with none of this applied. +// The policy — the verbosity, the source positions, the colour decision and the +// set of attribute keys that must never reach a log file — is sr-ht-ecore's +// logging.Defaults, because none of it is spec.sr.ht's to decide. -d, $LOG_LEVEL +// and [spec.sr.ht] log-level are how an operator addresses every daemon on this +// instance, and what must be redacted (the unified-login cookie, tokens.sr.ht +// working tokens, the Authorization header they travel in) is a fact about the +// instance rather than about this service. The local mask list is gone; the +// network-key and private-key entries it contributed are in the shared one, and +// so are the dsn and connection-string names it did not have. // -// The source position is on because most of what reaches this handler is a -// failure, and "which of the six render sites" is the first thing anybody asks. -// Colour is dropped when stderr is not a terminal, so the journal does not -// collect escape sequences. +// The handler stays here, and it is scribe's, because ecore deliberately builds +// none. Everything goes to stderr: a hook's stdout is forwarded to the pushing +// client, and this binary is both programs. // -// The masks are the reason to configure this in one place at all. This daemon -// handles the unified-login cookie and tokens.sr.ht working tokens, and a -// wrapped error or a struct logged whole is how a live credential reaches a log -// file — where it outlives the request, the process and usually the token's own -// lifetime. Masking is applied by the handler, so it holds for a log line -// nobody reviewed as well as for the ones here. -func newLogger() *slog.Logger { - level := new(slog.LevelVar) - level.Set(parseLevel(os.Getenv("LOG_LEVEL"))) - - stat, err := os.Stderr.Stat() - noColor := err != nil || stat.Mode()&os.ModeCharDevice == 0 - - return slog.New(scribe.NewTintHandler( +// logging.Install is what makes the library packages loggable at all. The read +// plane, the credential resolver and sr-ht-ecore's panic middleware all log +// through the default logger and none of them takes a *slog.Logger — a +// middleware in another module cannot be handed this one, and without the +// SetDefault its panic reports would come out of Go's plain stderr handler with +// none of the masking applied. +func installLogger(conf ini.File) *slog.Logger { + opts := logging.Defaults(conf, serviceName) + return logging.Install(scribe.NewTintHandler( scribe.WithWriter(os.Stderr), - scribe.WithLevel(level), - scribe.WithSource(true), - scribe.WithTimeFormat(time.DateTime), - scribe.WithNoColor(noColor), - scribe.WithMaskKeys("token", "cookie", "authorization", "network-key", "private-key"), - scribe.WithMask(`(?i)(secret|token|api_?key|password)`, "***"), + scribe.WithLevel(opts.Level), + scribe.WithSource(opts.AddSource), + scribe.WithTimeFormat(opts.TimeFormat), + scribe.WithNoColor(!opts.Color), + scribe.WithMaskKeys(opts.MaskKeys...), + scribe.WithMask(opts.MaskPattern, opts.MaskReplacement), )) } -func parseLevel(s string) slog.Level { - switch strings.ToLower(strings.TrimSpace(s)) { - case "debug": - return slog.LevelDebug - case "warn", "warning": - return slog.LevelWarn - case "error": - return slog.LevelError - default: - return slog.LevelInfo - } -} - -func run(log *slog.Logger) error { - // LoadConfig never fails on a missing file — it returns a nil ini.File — - // so validateConfig is what turns an unconfigured instance into one clear +func run(conf ini.File, log *slog.Logger) error { + // The config was read in main, before the logger, so that a verbosity written + // in config.ini is in force for the first line this process writes. It never + // fails on a missing file — core-go's LoadConfig returns a nil ini.File — so + // validateConfig is what turns an unconfigured instance into one clear // message instead of a panic deep inside the first request. - conf := config.LoadConfig() cfg, err := validateConfig(conf) if err != nil { return err diff --git a/cmd/specsrht/main_test.go b/cmd/specsrht/main_test.go index 7f78e0c03b13b9c7db8b0f4672f196cfaa294990..df2f13d7cc12f8977c2c65ad08cfab7d04ab8955 100644 --- a/cmd/specsrht/main_test.go +++ b/cmd/specsrht/main_test.go @@ -1,7 +1,6 @@ package main import ( - "log/slog" "strings" "testing" @@ -135,24 +134,6 @@ t.Fatal("validateConfig accepted a blank network-key") } if !strings.Contains(err.Error(), "[sr.ht] network-key") { t.Errorf("the error does not name the blank key:\n%v", err) - } -} - -func TestParseLevel(t *testing.T) { - tests := map[string]slog.Level{ - "": slog.LevelInfo, - "info": slog.LevelInfo, - "nonsense": slog.LevelInfo, - "debug": slog.LevelDebug, - " DEBUG ": slog.LevelDebug, - "warn": slog.LevelWarn, - "warning": slog.LevelWarn, - "error": slog.LevelError, - } - for in, want := range tests { - if got := parseLevel(in); got != want { - t.Errorf("parseLevel(%q) = %v want %v", in, got, want) - } } }