~bigbes/sr-ht-spec

0a32fd7a58ef967cab397053f9f3b59abd719375 — Eugene Blikh 9 days ago b7d1bf8
logging: take the instance's log policy from ecore
2 files changed, 50 insertions(+), 77 deletions(-)

M cmd/specsrht/main.go
M cmd/specsrht/main_test.go
M cmd/specsrht/main.go => cmd/specsrht/main.go +50 -58
@@ 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 @@ import (
	_ "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 @@ func main() {
		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 @@ func main() {
		}
	}

	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 @@ func runSpace(args []string) error {
	}
}

// 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.
//
// 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 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 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(
// installLogger builds the process logger and makes it slog's default.
//
// 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 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.
//
// 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

M cmd/specsrht/main_test.go => cmd/specsrht/main_test.go +0 -19
@@ 1,7 1,6 @@
package main

import (
	"log/slog"
	"strings"
	"testing"



@@ 138,24 137,6 @@ func TestBlankIsMissing(t *testing.T) {
	}
}

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

// TestHookDispatchIsCheckedBeforeAnythingElse guards the one ordering in main
// that matters: a hook must not read a config file or open Postgres, because
// it runs once per ref of every push and its only job is to reach the daemon.