From 0638c16f7ac54e5ab2e398ac748c28a1475ebb04 Mon Sep 17 00:00:00 2001 From: Eugene Blikh Date: Wed, 19 Aug 2026 11:06:11 +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 the daemon next door 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, in a logging.go named after cmd/doltsrht's. 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 the first test this binary has had, 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/doltsrht-migrate/logging.go | 62 +++++++++++++++++++ cmd/doltsrht-migrate/main.go | 33 ++++++++--- cmd/doltsrht-migrate/main_test.go | 99 +++++++++++++++++++++++++++++++ go.mod | 2 +- go.sum | 2 + 5 files changed, 189 insertions(+), 9 deletions(-) create mode 100644 cmd/doltsrht-migrate/logging.go create mode 100644 cmd/doltsrht-migrate/main_test.go diff --git a/cmd/doltsrht-migrate/logging.go b/cmd/doltsrht-migrate/logging.go new file mode 100644 index 0000000000000000000000000000000000000000..3d33be4eb06afea363ab919883f6e21d71a6fc2e --- /dev/null +++ b/cmd/doltsrht-migrate/logging.go @@ -0,0 +1,62 @@ +package main + +import ( + "log/slog" + "os" + + "github.com/vaughan0/go-ini" + + "go.bigb.es/auxilia/scribe" + + "sourcecraft.dev/bigbes/sr-ht-ecore/logging" +) + +// installLogger installs the process-wide slog handler, and it is the daemon's: +// cmd/doltsrht/logging.go 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. The file is named after that one for +// the same reason. +// +// 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: the daemon next door had been +// masking a DSN correctly for as long as this binary had been printing one. +// +// 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 `doltsrht-migrate -d postgres up` would +// silently ask for debug logging as well. $LOG_LEVEL and [dolt.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), + // Colour is for a terminal; under systemd or a container's log + // collector the escapes are noise in the journal. + scribe.WithNoColor(!opts.Color), + // The masks are keyed on the attribute path, not on the message, so + // they cost nothing in prose and cannot be defeated by a sentence that + // happens to contain the word "token". This binary holds exactly one + // credential — the connection string — and brant is what prints it. + scribe.WithMaskKeys(opts.MaskKeys...), + scribe.WithMask(opts.MaskPattern, opts.MaskReplacement), + )) +} diff --git a/cmd/doltsrht-migrate/main.go b/cmd/doltsrht-migrate/main.go index 205fd574059952ce23e05e5d63657473bbf3d84f..97b0e47aa0ab43db69aea21e61b120670d4771d8 100644 --- a/cmd/doltsrht-migrate/main.go +++ b/cmd/doltsrht-migrate/main.go @@ -17,7 +17,7 @@ import ( "context" "errors" "fmt" - "log" + "log/slog" "os" "path/filepath" @@ -64,16 +64,17 @@ func main() { } conf := config.LoadConfig() + log := installLogger(conf) if a.Auto && !config.GetBool(conf, serviceName, "migrate-on-upgrade", false) { - log.Printf("doltsrht-migrate: [%s]migrate-on-upgrade disabled, exiting", serviceName) + log.Info(fmt.Sprintf("[%s]migrate-on-upgrade disabled, exiting", serviceName)) return } if a.DataSourceName == "" { dsn, ok := conf.Get(serviceName, "connection-string") if !ok || dsn == "" { - log.Fatalf("doltsrht-migrate: no [%s]connection-string configured", serviceName) + fatal(log, fmt.Errorf("no [%s]connection-string configured", serviceName)) } a.DataSourceName = dsn } @@ -83,12 +84,12 @@ func main() { a.Driver = &drv resolvePaths(conf, &a) - log.Printf("doltsrht-migrate: loading migrations from %s", a.Directory) + log.Info("loading migrations", "dir", a.Directory) if a.Init != nil { - log.Printf("doltsrht-migrate: initializing schema from %s", a.Init.Schema) + log.Info("initializing schema", "schema", a.Init.Schema) if err := initDatabase(&a); err != nil { - log.Fatalf("doltsrht-migrate: init failed: %v", err) + fatal(log, fmt.Errorf("init failed: %w", err)) } return } @@ -96,6 +97,22 @@ func main() { cli.RunWithArgs(&a.Args) } +// 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 +// "doltsrht-migrate: " 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 [dolt.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) +} + // resolvePaths picks the migrations directory and schema file when the user did // not override --dir: a ./migrations directory in the working tree (dev // checkout) wins, otherwise the installed assets path is used, mirroring @@ -107,10 +124,10 @@ func resolvePaths(conf ini.File, a *Args) { info, err := os.Stat("migrations") if err != nil && !errors.Is(err, os.ErrNotExist) { - log.Fatalf("doltsrht-migrate: checking ./migrations: %v", err) + fatal(slog.Default(), fmt.Errorf("checking ./migrations: %w", err)) } if err == nil && info.IsDir() { - log.Println("doltsrht-migrate: found ./migrations, using it") + slog.Info("found ./migrations, using it") return } diff --git a/cmd/doltsrht-migrate/main_test.go b/cmd/doltsrht-migrate/main_test.go new file mode 100644 index 0000000000000000000000000000000000000000..1084aa4f8d27a9b8b7eaefe3a402a3ef3021f99f --- /dev/null +++ b/cmd/doltsrht-migrate/main_test.go @@ -0,0 +1,99 @@ +package main + +import ( + "bytes" + "errors" + "os" + "os/exec" + "strings" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// 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 = "DOLTSRHT_MIGRATE_TEST_ARGV" + +func TestMain(m *testing.M) { + if argv, ok := os.LookupEnv(testArgvEnv); ok { + os.Args = append([]string{"doltsrht-migrate"}, 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) +} diff --git a/go.mod b/go.mod index ce584bc490b863fc8ae2ac83d48b6136a68543e9..395984236f4b84ebf19d1770b2feca03472b705f 100644 --- a/go.mod +++ b/go.mod @@ -20,7 +20,7 @@ require ( google.golang.org/grpc v1.79.3 gopkg.in/go-jose/go-jose.v2 v2.6.3 sourcecraft.dev/bigbes/sr-ht-core v0.0.0-20260816094344-effb7ced05b7 - sourcecraft.dev/bigbes/sr-ht-ecore v0.0.0-20260816081411-3bd158fbb232 + sourcecraft.dev/bigbes/sr-ht-ecore v0.0.0-20260819062744-9a4d2ed9dd21 ) require ( diff --git a/go.sum b/go.sum index 317cb048a8326784b232011dc7440677cb966c28..4fa886734456e7d18b0a3c19828f86ecdc42d93c 100644 --- a/go.sum +++ b/go.sum @@ -683,3 +683,5 @@ sourcecraft.dev/bigbes/sr-ht-core v0.0.0-20260816094344-effb7ced05b7 h1:YpwRaM3M sourcecraft.dev/bigbes/sr-ht-core v0.0.0-20260816094344-effb7ced05b7/go.mod h1:Mu1Vx39ws/OTKWGoVERXvkdRSPLBdhuFTYv0ftVV31c= sourcecraft.dev/bigbes/sr-ht-ecore v0.0.0-20260816081411-3bd158fbb232 h1:vfuiF+4BwTFyLOaxuuIGdyL22is6RN/7yF/CV35frTQ= sourcecraft.dev/bigbes/sr-ht-ecore v0.0.0-20260816081411-3bd158fbb232/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=