From a53c6d7ddd2d3718183838ae0354aa250ab4b892 Mon Sep 17 00:00:00 2001 From: Eugene Blikh Date: Wed, 19 Aug 2026 11:09:43 +0300 Subject: [PATCH] migrate: install the instance's masking before brant can log a DSN brant reports a migration directory it cannot open with slog.Error("failed to create provider", "datasource", a.DataSourceName, ...) -- the connection string, password and all, at ERR level. A missing directory is what an installed package is in until its first migration ships, so this is an ordinary path rather than an exotic one. This binary installed no slog handler at all, so that record went to Go's built-in stderr handler and no mask list of any kind applied -- while cmd/specsrht had been masking a DSN correctly for as long as this one had been printing one. It now installs the same handler from the same policy. The verbosity comes from DefaultsWithoutDebugFlag, because -d here is brant's --dialect and takes a value. Half a fix without the ecore bump: "datasource" was not a spelling the mask list knew until 9a4d2ed. Both halves are pinned by a subprocess test, and removing either turns it red. The log package goes with it. slog.SetDefault reroutes the std logger through the installed handler at info level, so a log.Fatalf left behind would be silently dropped by an operator's log-level=warn -- an error message swallowed by a logging preference. Not fixable from here: brant's cli.initLogger runs ahead of that record and under --json replaces the installed handler with a plain JSON one of its own. Nothing passes --json; the default branch leaves the handler alone. --- cmd/specsrht-migrate/main.go | 76 +++++++++++++++++++++++--- cmd/specsrht-migrate/main_test.go | 91 +++++++++++++++++++++++++++++++ go.mod | 2 +- go.sum | 2 + 4 files changed, 162 insertions(+), 9 deletions(-) diff --git a/cmd/specsrht-migrate/main.go b/cmd/specsrht-migrate/main.go index bad16afc7b0914d6f39903417ffbb5a01520c6c6..10e3a34c758756bef7166ec495b503fd41915af6 100644 --- a/cmd/specsrht-migrate/main.go +++ b/cmd/specsrht-migrate/main.go @@ -25,7 +25,7 @@ import ( "context" "errors" "fmt" - "log" + "log/slog" "os" "path/filepath" @@ -35,7 +35,10 @@ 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-core/config" + "sourcecraft.dev/bigbes/sr-ht-ecore/logging" ) const ( @@ -101,15 +104,16 @@ func main() { } conf := config.LoadConfig() + log := installLogger(conf) if a.Auto && !config.GetBool(conf, serviceName, "migrate-on-upgrade", false) { - log.Printf("%s: [%s]migrate-on-upgrade disabled, exiting", progName, serviceName) + log.Info(fmt.Sprintf("[%s]migrate-on-upgrade disabled, exiting", serviceName)) return } dsn, err := resolveDSN(conf, a.DataSourceName) if err != nil { - log.Fatalf("%s: %v", progName, err) + fatal(log, err) } a.DataSourceName = dsn @@ -118,14 +122,14 @@ func main() { a.Driver = &drv if err := resolvePaths(conf, a); err != nil { - log.Fatalf("%s: %v", progName, err) + fatal(log, err) } - log.Printf("%s: loading migrations from %s", progName, a.Directory) + log.Info("loading migrations", "dir", a.Directory) if a.Init != nil { - log.Printf("%s: initializing schema from %s", progName, a.Init.Schema) + log.Info("initializing schema", "schema", a.Init.Schema) if err := initDatabase(a); err != nil { - log.Fatalf("%s: init failed: %v", progName, err) + fatal(log, fmt.Errorf("init failed: %w", err)) } return } @@ -133,6 +137,62 @@ func main() { cli.RunWithArgs(&a.Args) } +// installLogger installs the process-wide slog handler, and it is the daemon's: +// cmd/specsrht's installLogger builds the same scribe handler over the same +// sr-ht-ecore policy, so a migration and the daemon that starts after it are +// read the same way in the same journal. +// +// Installing it at all is the point rather than the tidiness. brant reports a +// migration directory it cannot open with +// `slog.Error("failed to create provider", "datasource", a.DataSourceName, ...)` +// — the connection string, password and all, at ERR level, on the ordinary path +// an installed package takes before its first migration ships. Without this call +// that record goes to Go's built-in stderr handler, which knows no mask list, so +// the redaction sr-ht-ecore maintains never gets a chance to run. It was the +// install that was missing here, not the list. +// +// One thing no mask list can fix: brant's own cli.initLogger runs inside +// ProviderFromArgs, ahead of that record, and under --json it calls +// slog.SetDefault with a plain JSON handler of its own — which throws this one +// away and prints the DSN again. Nothing here passes --json and nothing should +// start; the default branch only redirects the std log package and leaves the +// installed handler alone, which is why the masking holds. +// +// The verbosity comes from DefaultsWithoutDebugFlag rather than the daemon's +// Defaults, and that is the one place the two differ: ecore reads a standalone +// -d out of os.Args as SourceHut's debug flag, while here -d is brant's +// --dialect and takes a value, so `specsrht-migrate -d postgres up` would +// silently ask for debug logging as well. $LOG_LEVEL and [spec.sr.ht]log-level +// still resolve, which is what an operator debugging an upgrade hook reaches +// for. +func installLogger(conf ini.File) *slog.Logger { + opts := logging.DefaultsWithoutDebugFlag(conf, serviceName) + return logging.Install(scribe.NewTintHandler( + scribe.WithWriter(os.Stderr), + 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), + )) +} + +// fatal reports why this binary is stopping and stops it. It replaces +// log.Fatalf, which slog has no equivalent of on purpose: os.Exit runs no +// deferred function, so "say why and die" is a decision only main may take. +// +// The error is the record's message rather than an attribute, and the progName +// prefix every one of these lines used to carry is gone. Both follow from the +// reader: these are whole sentences written for the operator watching an upgrade +// — "no [spec.sr.ht]connection-string configured" is the entire report — and an +// attribute would quote and escape it behind a key, while the unit name and the +// source position the handler already stamps say what the prefix used to. +func fatal(log *slog.Logger, err error) { + log.Error(err.Error()) + os.Exit(1) +} + // resolveDSN picks the connection string: an explicit --dsn (or BRANT_DSN) wins, // otherwise [spec.sr.ht]connection-string. A missing or empty configured value // is an error rather than a silent connection attempt against a default DSN. @@ -161,7 +221,7 @@ func resolvePaths(conf ini.File, a *Args) error { return fmt.Errorf("checking ./migrations: %w", err) } if err == nil && info.IsDir() { - log.Printf("%s: found ./migrations, using it", progName) + slog.Info("found ./migrations, using it") return nil } diff --git a/cmd/specsrht-migrate/main_test.go b/cmd/specsrht-migrate/main_test.go index 64f65e4f4b6e58b0be055ea61eacd8fe266ca9e2..85c12f4458a0fada44ffbe2c51481cabe14ffa88 100644 --- a/cmd/specsrht-migrate/main_test.go +++ b/cmd/specsrht-migrate/main_test.go @@ -1,21 +1,112 @@ package main import ( + "bytes" "context" "crypto/rand" "database/sql" "encoding/hex" + "errors" "net/url" "os" + "os/exec" "path/filepath" "strings" "testing" "git.sr.ht/~bitfehler/brant/cli" "github.com/alexflint/go-arg" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" "github.com/vaughan0/go-ini" ) +// testArgvEnv turns a re-executed copy of this test binary into the migrate +// binary itself: TestMain sees it, replaces os.Args with its whitespace-split +// value and calls main(). +// +// Running main() in a subprocess is the only way to observe what main() does. +// It reads the config off the filesystem through config.LoadConfig, the record +// under test is written by a library past every seam a unit test could reach, +// and the run ends in os.Exit — which takes the process with it. What is under +// test is what an operator finds in the upgrade log, so the test has to read +// that log. +const testArgvEnv = "SPECSRHT_MIGRATE_TEST_ARGV" + +func TestMain(m *testing.M) { + if argv, ok := os.LookupEnv(testArgvEnv); ok { + os.Args = append([]string{progName}, strings.Fields(argv)...) + main() + os.Exit(0) + } + os.Exit(m.Run()) +} + +// runMain runs main() in a subprocess whose working directory is empty — no +// config.ini, no ./migrations — and returns everything the process wrote and the +// status it exited with. +// +// Stdout and stderr are interleaved into one buffer because that is how a +// package manager's upgrade log shows them, and the question this asks is what +// an operator finds there. +func runMain(t *testing.T, argv string) (output string, code int) { + t.Helper() + + exe, err := os.Executable() + require.NoError(t, err, "locate the test binary to re-execute") + + cmd := exec.Command(exe) + cmd.Dir = t.TempDir() + cmd.Env = append(os.Environ(), testArgvEnv+"="+argv) + var buf bytes.Buffer + cmd.Stdout = &buf + cmd.Stderr = &buf + + err = cmd.Run() + var exit *exec.ExitError + switch { + case err == nil: + code = 0 + case errors.As(err, &exit): + code = exit.ExitCode() + default: + require.NoError(t, err, "run %s %s", exe, argv) + } + return buf.String(), code +} + +// testPassword is a fake credential no configuration on this instance holds. It +// is written into the DSN the test passes and looked for in everything the +// process wrote; a real one would put the thing under test into the test log. +const testPassword = "HUNTER2SECRET" + +// TestMainDoesNotPrintTheConnectionString pins the reason main() installs a +// logger at all. +// +// brant reports a migration directory it cannot open with +// `slog.Error("failed to create provider", "datasource", a.DataSourceName, ...)` +// — the connection string, password and all, at ERR level. A missing directory +// is not an exotic state: it is what an installed package is in until its first +// migration ships. Two things have to hold for the password not to reach the +// journal, and this asserts through both: the key "datasource" must be in the +// instance's mask list (sr-ht-ecore's, which did not know that spelling until it +// was added), and a handler carrying that list must be slog's default by the +// time brant writes, or the record goes to Go's built-in stderr handler and no +// list of any kind applies. +func TestMainDoesNotPrintTheConnectionString(t *testing.T) { + out, code := runMain(t, + "up --dir /nonexistent --dsn postgresql://u:"+testPassword+"@localhost/x") + + // The run must actually reach brant and fail there, or the assertions below + // would pass over an empty log. + assert.NotZero(t, code, "the missing directory must still be a failed run: %s", out) + assert.Contains(t, out, "failed to create provider", + "the leaking record must have been written at all: %s", out) + + assert.NotContains(t, out, testPassword, "the DSN reached the log in the clear: %s", out) + assert.Contains(t, out, "datasource=***", "%s", out) +} + // testParse parses argv the way main() does, except that the environment is // ignored: BRANT_DSN / BRANT_MIGRATION_DIR / BRANT_DIALECT in a developer's // shell would otherwise silently change the defaults under test. diff --git a/go.mod b/go.mod index 8061cfa5d877d2df44e331c39260706de61a1897..a3d5d190d7f964941bf648bd25de4454f8ba24b2 100644 --- a/go.mod +++ b/go.mod @@ -22,7 +22,7 @@ require ( go.bigb.es/auxilia v0.7.0 gopkg.in/yaml.v3 v3.0.1 sourcecraft.dev/bigbes/sr-ht-core v0.0.0-20260816094344-effb7ced05b7 - sourcecraft.dev/bigbes/sr-ht-ecore v0.0.0-20260816184219-89fa694cbf54 + sourcecraft.dev/bigbes/sr-ht-ecore v0.0.0-20260819062744-9a4d2ed9dd21 ) require ( diff --git a/go.sum b/go.sum index 99a0c87eeccfa666fb16e041762805043a167ca8..2e47a4a5e20f27c4c58ed68ceb8ca466e7a2993b 100644 --- a/go.sum +++ b/go.sum @@ -425,3 +425,5 @@ sourcecraft.dev/bigbes/sr-ht-ecore v0.0.0-20260816081411-3bd158fbb232 h1:vfuiF+4 sourcecraft.dev/bigbes/sr-ht-ecore v0.0.0-20260816081411-3bd158fbb232/go.mod h1:Hu5gSbJ9ZQup0KGfupXRxeako5ajV86zB6fC2DbleWY= sourcecraft.dev/bigbes/sr-ht-ecore v0.0.0-20260816184219-89fa694cbf54 h1:odN8rYDbV7ieJmYbULr1+9v6yvAmwpXY54Sk2ydEhkM= sourcecraft.dev/bigbes/sr-ht-ecore v0.0.0-20260816184219-89fa694cbf54/go.mod h1:Hu5gSbJ9ZQup0KGfupXRxeako5ajV86zB6fC2DbleWY= +sourcecraft.dev/bigbes/sr-ht-ecore v0.0.0-20260819062744-9a4d2ed9dd21 h1:ygXEX3l5jA1VpB46RG7Yte3eabNUr+isnW1r7MP54hU= +sourcecraft.dev/bigbes/sr-ht-ecore v0.0.0-20260819062744-9a4d2ed9dd21/go.mod h1:Hu5gSbJ9ZQup0KGfupXRxeako5ajV86zB6fC2DbleWY=