From 27823bb627b12760176e7dfa2aaa3a0c8aae1fe0 Mon Sep 17 00:00:00 2001 From: Eugene Blikh Date: Sat, 8 Aug 2026 23:01:36 +0300 Subject: [PATCH] log: replace logrus with slog behind auxilia's scribe handler MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Every logger field this service owned was a *logrus.Entry threaded through a constructor, which is what logrus costs for want of a usable default. They are slog.Default().With("component", ...) now, and the threading is gone with them; the shared middleware's panic reports land in the same handler, which is why the daemon sets the default before anything that can fail. The handler is scribe's tint handler: level from [dolt.sr.ht]log-level, source positions, and masks keyed on the attribute path for the three credentials this service handles — the unified-login cookie, the Internal fernet token and the Authorization header the remotesapi reads a PAT or a keypair JWT out of. Errors go through scribe.Err, so a culpa error's hint reaches the operator on its own line. logrus stays in go.mod: dolt's remotesrv.ServerArgs takes a *logrus.Entry and nothing else. It is now confined to Config.DoltLogger, which is the only place this service names it. dolt-git-hook is deliberately untouched: what it writes to stderr is the notice a pushing user reads through git, not a log. --- authn/cookie.go | 7 ++-- authn/jwt.go | 10 ++++-- cmd/doltsrht/logging.go | 60 ++++++++++++++++++++++++++++++++++ cmd/doltsrht/main.go | 55 +++++++++++++++++++++---------- config.example.ini | 5 +++ go.mod | 7 ++-- go.sum | 18 +++++----- remoteapi/credsvc.go | 20 ++++++------ remoteapi/integration_test.go | 11 +++++-- remoteapi/interceptors.go | 40 ++++++++++++++--------- remoteapi/interceptors_test.go | 14 ++++++-- remoteapi/server.go | 25 +++++++------- web/templates.go | 7 ++-- 13 files changed, 200 insertions(+), 79 deletions(-) create mode 100644 cmd/doltsrht/logging.go diff --git a/authn/cookie.go b/authn/cookie.go index 8084e2e75e855a511404a632991c7bc4487bde99..a4edfaebd1bdd155bc2ccf73cc717d04161ff8d1 100644 --- a/authn/cookie.go +++ b/authn/cookie.go @@ -2,9 +2,11 @@ package authn import ( "encoding/json" - "log" + "log/slog" "net/http" + "go.bigb.es/auxilia/scribe" + "sourcecraft.dev/bigbes/sr-ht-core/auth" "sourcecraft.dev/bigbes/sr-ht-core/crypto" ) @@ -67,7 +69,8 @@ func resolveCookie(r *http.Request) *auth.AuthContext { if err := meta.LookupUser(r.Context(), authCookie.Name, &ac); err != nil { // meta/database unreachable or unknown user: degrade to anonymous // rather than failing the request (browsing must keep working). - log.Printf("authn: cookie LookupUser(%q): %v", authCookie.Name, err) + slog.WarnContext(r.Context(), "resolving the login cookie's user failed", + "component", "authn", "username", authCookie.Name, scribe.Err(err)) return nil } ac.AuthMethod = auth.AUTH_COOKIE diff --git a/authn/jwt.go b/authn/jwt.go index e02a1c4a92ca49a4ed3dac097553eebda05215fc..6513cd40243a82cd74ff6e73b2c16eab7c2d2f0d 100644 --- a/authn/jwt.go +++ b/authn/jwt.go @@ -5,13 +5,16 @@ import ( "crypto/ed25519" "crypto/subtle" "fmt" - "log" + "log/slog" "time" - "sourcecraft.dev/bigbes/sr-ht-core/auth" "github.com/dolthub/dolt/go/libraries/doltcore/creds" jose "gopkg.in/go-jose/go-jose.v2" "gopkg.in/go-jose/go-jose.v2/jwt" + + "go.bigb.es/auxilia/scribe" + + "sourcecraft.dev/bigbes/sr-ht-core/auth" ) // jwtSubjectPrefix is the fixed prefix dolt puts in the JWT "sub" claim, @@ -110,7 +113,8 @@ func ResolveDoltJWT(ctx context.Context, rawJWT, expectedAud string, keys KeySto if err := keys.TouchLastUsed(ctx, kid); err != nil { // Non-fatal: the caller is already authenticated; last_used is display // metadata. Log and continue rather than failing the clone/push. - log.Printf("authn: TouchLastUsed(%q): %v", kid, err) + slog.WarnContext(ctx, "recording the last use of a dolt key failed", + "component", "authn", "kid", kid, scribe.Err(err)) } return &ac, nil } diff --git a/cmd/doltsrht/logging.go b/cmd/doltsrht/logging.go new file mode 100644 index 0000000000000000000000000000000000000000..cb03a0c53d21fc9a95ea27180ee6f1589fc0b757 --- /dev/null +++ b/cmd/doltsrht/logging.go @@ -0,0 +1,60 @@ +package main + +import ( + "log/slog" + "os" + "time" + + "github.com/vaughan0/go-ini" + + "go.bigb.es/auxilia/scribe" + + "sourcecraft.dev/bigbes/sr-ht-core/config" +) + +// setupLogging installs the process-wide slog handler. +// +// It sets the *default* logger rather than building one to thread through +// constructors, and that is the point rather than a shortcut. sr-ht-ecore's +// middleware reports a recovered panic through slog's default; so does every +// library package in this service that has no constructor to be handed a logger +// through (authn's cookie and JWT resolvers, the web renderer). A daemon that +// skipped this call would still log all of it — into Go's plain stderr handler, +// without a level, without source positions, and above all without the masking +// below. +// +// The level comes from [dolt.sr.ht]log-level ("debug", "info", "warn", +// "error"); an unreadable value is info, because a daemon that refused to boot +// over a typo in a log level would be trading an operator's whole service for +// their logging preference. +func setupLogging(conf ini.File) { + var level slog.Level + if err := level.UnmarshalText([]byte(config.GetString(conf, serviceName, "log-level", "info"))); err != nil { + level = slog.LevelInfo + } + + slog.SetDefault(slog.New(scribe.NewTintHandler( + scribe.WithWriter(os.Stderr), + scribe.WithLevel(level), + scribe.WithSource(true), + scribe.WithTimeFormat(time.DateTime), + // Colour is for a terminal; under systemd or a container's log + // collector the escapes are noise in the journal. + scribe.WithNoColor(!isTerminal(os.Stderr)), + // 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". These three are the credentials + // this service handles: the unified-login cookie, the "Internal" + // service-to-service fernet token and the Authorization header the + // remotesapi interceptors read a PAT or a keypair JWT out of. + scribe.WithMaskKeys("token", "cookie", "authorization"), + scribe.WithMask(`(?i)(secret|token|api_?key|password|pubkey|credential)`, "***"), + ))) +} + +// isTerminal reports whether f is a character device, which is the whole of +// what the colour decision needs and does not require a dependency to answer. +func isTerminal(f *os.File) bool { + info, err := f.Stat() + return err == nil && info.Mode()&os.ModeCharDevice != 0 +} diff --git a/cmd/doltsrht/main.go b/cmd/doltsrht/main.go index 1c3107968905516ecdd7517832f4ba2bec319eef..610f30c2ae816e6cad3856766505701330a08db0 100644 --- a/cmd/doltsrht/main.go +++ b/cmd/doltsrht/main.go @@ -21,16 +21,18 @@ import ( "context" "database/sql" "fmt" - "log" + "log/slog" "net/url" "os" "github.com/go-chi/chi/v5" chimw "github.com/go-chi/chi/v5/middleware" _ "github.com/lib/pq" // registers the "postgres" database/sql driver - "github.com/sirupsen/logrus" "github.com/vaughan0/go-ini" + "go.bigb.es/auxilia/culpa" + "go.bigb.es/auxilia/scribe" + "sourcecraft.dev/bigbes/sr-ht-core/config" "sourcecraft.dev/bigbes/sr-ht-core/database" "sourcecraft.dev/bigbes/sr-ht-core/server" @@ -94,12 +96,19 @@ type settings struct { func resolveSettings(conf ini.File) (settings, error) { connString, ok := conf.Get(serviceName, "connection-string") if !ok || connString == "" { - return settings{}, fmt.Errorf("missing required [%s]connection-string in config.ini", serviceName) + // A hint rather than a longer sentence: scribe prints it on its own + // line, and what an operator meeting this needs is the key to add, not + // a restatement of the failure. + return settings{}, culpa.WithHint( + culpa.New("no connection-string is configured"), + "set [dolt.sr.ht]connection-string in config.ini") } host, err := hostFromOrigin(config.GetOrigin(conf, serviceName, true)) if err != nil { - return settings{}, fmt.Errorf("[%s]origin: %w", serviceName, err) + return settings{}, culpa.WithHint( + culpa.Wrapf(err, "[%s]origin", serviceName), + "origin must be protocol://host; it is what places this service in every other service's nav") } return settings{ @@ -134,6 +143,10 @@ func hostFromOrigin(origin string) (string, error) { func main() { conf := config.LoadConfig() + // Before anything that can fail: everything below, and every library this + // process links, reports through slog's default logger. + setupLogging(conf) + // server.New parses -b/-d/-m/-p and runs crypto.InitCrypto (needs // [sr.ht]network-key + [webhooks]private-key; missing keys panic here). // Pass the full os.Args: core-go's getopt skips argv[0] as the program name @@ -145,16 +158,14 @@ func main() { cfg, err := resolveSettings(conf) if err != nil { - log.Fatalf("doltsrht: %v", err) + fatal("reading the configuration", err) } db, err := sql.Open("postgres", cfg.connString) if err != nil { - log.Fatalf("doltsrht: open postgres: %v", err) + fatal("opening the postgres pool", err) } - logger := logrus.NewEntry(logrus.StandardLogger()) - // Build the remotesapi server first: its chunk-store cache backs the web // store manager's Evict. rapiConf := remoteapi.Config{ @@ -164,15 +175,14 @@ func main() { ListenAddr: cfg.remotesapiAddr, CredsListenAddr: cfg.credsapiAddr, HttpHost: cfg.httpHost, - Logger: logger, } rsrv, err := remoteapi.New(rapiConf) if err != nil { - log.Fatalf("doltsrht: build remotesapi server: %v", err) + fatal("building the remotesapi server", err) } csrv, err := remoteapi.NewCredServer(rapiConf) if err != nil { - log.Fatalf("doltsrht: build credentials server: %v", err) + fatal("building the credentials server", err) } stores := &storeManager{cache: rsrv.Cache()} @@ -195,7 +205,7 @@ func main() { return storage.RepoDiskPath(cfg.reposRoot, owner, name) }, }); err != nil { - log.Fatalf("doltsrht: web.Register: %v", err) + fatal("mounting the web routes", err) } }) @@ -203,24 +213,35 @@ func main() { // goroutines and let the web server's Run own the SIGINT lifecycle. go func() { if err := rsrv.Serve(); err != nil { - log.Fatalf("doltsrht: remotesapi serve: %v", err) + fatal("serving the remotesapi", err) } }() go func() { if err := csrv.Serve(); err != nil { - log.Fatalf("doltsrht: credentials serve: %v", err) + fatal("serving the credentials api", err) } }() - logger.Infof("doltsrht: remotesapi on %s, credentials on %s, web on %s", - cfg.remotesapiAddr, cfg.credsapiAddr, defaultWebAddr) + slog.Info("listening", + "remotesapi", cfg.remotesapiAddr, + "credentials", cfg.credsapiAddr, + "web", defaultWebAddr) // Blocks until SIGINT, then returns after draining the web listeners. srv.Run() // GracefulStop on the remotesapi server also closes every memoized chunk // store (its cache Close), so no separate storage cache Close is needed. - logger.Info("doltsrht: stopping gRPC servers") + slog.Info("stopping the grpc servers") rsrv.GracefulStop() csrv.GracefulStop() } + +// fatal reports a startup failure and ends the process. slog has no Fatal, on +// the argument that a logging call should not decide a program's lifetime; this +// is the one place in this binary that wants both, so it is written once here +// rather than as an Error/Exit pair at every call site. +func fatal(doing string, err error) { + slog.Error(doing+" failed", scribe.Err(err)) + os.Exit(1) +} diff --git a/config.example.ini b/config.example.ini index 32d95d151ee76855200ccad83f0bdc57d069448f..756bb0fcfc91d0a76e0961cb8930c02eca63831e 100644 --- a/config.example.ini +++ b/config.example.ini @@ -38,6 +38,11 @@ static-dir=/usr/share/sourcehut/dolt.sr.ht/static ; ; Set to "yes" to run brant migrations automatically on package upgrade. migrate-on-upgrade=yes +; +; Verbosity of the daemon's structured log: debug, info, warn or error. An +; unreadable value is read as info rather than refusing to boot — a typo in a +; logging preference must not cost the service. +log-level=info ; --------------------------------------------------------------------------- ; Shared keys reused in place (owned by other services, listed for reference; diff --git a/go.mod b/go.mod index ddf9bb56121846fed6c185f4358907bd42ab891f..43b5e492ae8e997258a5429824d890109ce8300f 100644 --- a/go.mod +++ b/go.mod @@ -9,9 +9,10 @@ require ( github.com/fernet/fernet-go v0.0.0-20211208181803-9f70042a33ee github.com/go-chi/chi/v5 v5.3.1 github.com/lib/pq v1.10.9 - github.com/sirupsen/logrus v1.8.3 + github.com/sirupsen/logrus v1.9.3 github.com/stretchr/testify v1.11.1 github.com/vaughan0/go-ini v0.0.0-20130923145212-a98ad7ee00ec + go.bigb.es/auxilia v0.5.0 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-20260718185800-dd418a200152 @@ -67,7 +68,7 @@ require ( github.com/aws/aws-sdk-go-v2/service/sts v1.35.1 // indirect github.com/aws/smithy-go v1.24.2 // indirect github.com/beorn7/perks v1.0.1 // indirect - github.com/cenkalti/backoff/v4 v4.1.3 // indirect + github.com/cenkalti/backoff/v4 v4.3.0 // indirect github.com/cespare/xxhash/v2 v2.3.0 // indirect github.com/cloudflare/circl v1.6.0 // indirect github.com/cncf/xds/go v0.0.0-20251210132809-ee656c7534f5 // indirect @@ -153,7 +154,7 @@ require ( go.uber.org/multierr v1.10.0 // indirect go.uber.org/zap v1.27.0 // indirect go.yaml.in/yaml/v2 v2.4.2 // indirect - golang.org/x/crypto v0.51.0 // indirect + golang.org/x/crypto v0.52.0 // indirect golang.org/x/net v0.54.0 // indirect golang.org/x/oauth2 v0.34.0 // indirect golang.org/x/sync v0.20.0 // indirect diff --git a/go.sum b/go.sum index efdf7496507a870e0456c0c8ad1843dd89f5c722..d6e24d865657afbc787986614cf8b3ee8c5cc36a 100644 --- a/go.sum +++ b/go.sum @@ -140,8 +140,8 @@ github.com/beorn7/perks v1.0.0/go.mod h1:KWe93zE9D1o94FZ5RNwFwVgaQK1VOXiVxmqh+Ce github.com/beorn7/perks v1.0.1 h1:VlbKKnNfV8bJzeqoa4cOKqO6bYr3WgKZxO8Z16+hsOM= github.com/beorn7/perks v1.0.1/go.mod h1:G2ZrVWU2WbWT9wwq4/hrbKbnv/1ERSJQ0ibhJ6rlkpw= github.com/bwesterb/go-ristretto v1.2.3/go.mod h1:fUIoIZaG73pV5biE2Blr2xEzDoMj7NFEuV9ekS419A0= -github.com/cenkalti/backoff/v4 v4.1.3 h1:cFAlzYUlVYDysBEH2T5hyJZMh3+5+WCBvSnK6Q8UtC4= -github.com/cenkalti/backoff/v4 v4.1.3/go.mod h1:scbssz8iZGpm3xbr14ovlUdkxfGXNInqkPWOWmG2CLw= +github.com/cenkalti/backoff/v4 v4.3.0 h1:MyRJ/UdXutAwSAT+s3wNd7MfTIcy71VQueUuFK343L8= +github.com/cenkalti/backoff/v4 v4.3.0/go.mod h1:Y3VNntkOUPxTVeUxJ/G5vcM//AlwfmyYozVcomhLiZE= github.com/cespare/xxhash/v2 v2.1.1/go.mod h1:VGX0DQ3Q6kWi7AoAeZDth3/j3BFtOZR5XLFGgcrjCOs= github.com/cespare/xxhash/v2 v2.3.0 h1:UL815xU9SqsFlibzuggzjXhog7bL6oX9BbNZnL2UFvs= github.com/cespare/xxhash/v2 v2.3.0/go.mod h1:VGX0DQ3Q6kWi7AoAeZDth3/j3BFtOZR5XLFGgcrjCOs= @@ -416,8 +416,8 @@ github.com/sergi/go-diff v1.3.1 h1:xkr+Oxo4BOQKmkn/B9eMK0g5Kg/983T9DqqPHwYqD+8= github.com/sergi/go-diff v1.3.1/go.mod h1:aMJSSKb2lpPvRNec0+w3fl7LP9IOFzdc9Pa4NFbPK1I= github.com/sirupsen/logrus v1.2.0/go.mod h1:LxeOpSwHxABJmUn/MG1IvRgCAasNZTLOkJPxbbu5VWo= github.com/sirupsen/logrus v1.4.2/go.mod h1:tLMulIdttU9McNUspp0xgXVQah82FyeX6MwdIuYE2rE= -github.com/sirupsen/logrus v1.8.3 h1:DBBfY8eMYazKEJHb3JKpSPfpgd2mBCoNFlQx6C5fftU= -github.com/sirupsen/logrus v1.8.3/go.mod h1:naHLuLoDiP4jHNo9R0sCBMtWGeIprob74mVsIT4qYEQ= +github.com/sirupsen/logrus v1.9.3 h1:dueUQJ1C2q9oE3F7wvmSGAaVtTmUizReu6fjN8uqzbQ= +github.com/sirupsen/logrus v1.9.3/go.mod h1:naHLuLoDiP4jHNo9R0sCBMtWGeIprob74mVsIT4qYEQ= github.com/skratchdot/open-golang v0.0.0-20200116055534-eef842397966 h1:JIAuq3EEf9cgbU6AtGPK4CTG3Zf6CKMNqf0MHTggAUA= github.com/skratchdot/open-golang v0.0.0-20200116055534-eef842397966/go.mod h1:sUM3LWHvSMaG192sy56D9F7CNvL7jUJVXoqM1QKLnog= github.com/sony/gobreaker v0.5.0 h1:dRCvqm0P490vZPmy7ppEk2qCnCieBooFJ+YoXGYB+yg= @@ -469,6 +469,8 @@ github.com/zeebo/blake3 v0.2.3 h1:TFoLXsjeXqRNFxSbk35Dk4YtszE/MQQGK10BH4ptoTg= github.com/zeebo/blake3 v0.2.3/go.mod h1:mjJjZpnsyIVtVgTOSpJ9vmRE4wgDeyt2HU3qXvvKCaQ= github.com/zeebo/xxh3 v1.0.2 h1:xZmwmqxHZA8AI603jOQ0tMqmBr9lPeFwGg6d+xy9DC0= github.com/zeebo/xxh3 v1.0.2/go.mod h1:5NWz9Sef7zIDm2JHfFlcQvNekmcEl9ekUZQQKCYaDcA= +go.bigb.es/auxilia v0.5.0 h1:S5+btW6++4CQDOfAEZe1UxrXRl6nxtmu0rI3uIXwCaQ= +go.bigb.es/auxilia v0.5.0/go.mod h1:hBkJvydQRfmgSTR2U4PvYgJcZnh7Bj/otukrk14iJU4= go.opentelemetry.io/auto/sdk v1.2.1 h1:jXsnJ4Lmnqd11kwkBV2LgLoFMZKizbCi5fNZ/ipaZ64= go.opentelemetry.io/auto/sdk v1.2.1/go.mod h1:KRTj+aOaElaLi+wW1kO/DZRXwkF4C5xPbEe3ZiIhN7Y= go.opentelemetry.io/contrib/detectors/gcp v1.39.0 h1:kWRNZMsfBHZ+uHjiH4y7Etn2FK26LAGkNFw7RHv1DhE= @@ -504,8 +506,8 @@ golang.org/x/crypto v0.0.0-20210921155107-089bfa567519/go.mod h1:GvvjBRRGRdwPK5y golang.org/x/crypto v0.3.1-0.20221117191849-2c476679df9a/go.mod h1:hebNnKkNXi2UzZN1eVRvBB7co0a+JxK6XbPiWVs/3J4= golang.org/x/crypto v0.7.0/go.mod h1:pYwdfH91IfpZVANVyUOhSIPZaFoJGxTFbZhFTx+dXZU= golang.org/x/crypto v0.17.0/go.mod h1:gCAAfMLgwOJRpTjQ2zCCt2OcSfYMTeZVSRtQlPC7Nq4= -golang.org/x/crypto v0.51.0 h1:IBPXwPfKxY7cWQZ38ZCIRPI50YLeevDLlLnyC5wRGTI= -golang.org/x/crypto v0.51.0/go.mod h1:8AdwkbraGNABw2kOX6YFPs3WM22XqI4EXEd8g+x7Oc8= +golang.org/x/crypto v0.52.0 h1:RMs7fP2rXdep0CftQlK8Uf+kibLm7qkCcradZWYz988= +golang.org/x/crypto v0.52.0/go.mod h1:1QgfPxDqh0T2M/elOJtp9RvuR95kVjir0e6/BvEmGbc= golang.org/x/exp v0.0.0-20180321215751-8460e604b9de/go.mod h1:CJ0aWSM057203Lf6IL+f9T1iT9GByDxfZKAQTCR3kQA= golang.org/x/exp v0.0.0-20180807140117-3d87b88a115f/go.mod h1:CJ0aWSM057203Lf6IL+f9T1iT9GByDxfZKAQTCR3kQA= golang.org/x/exp v0.0.0-20190125153040-c74c464bbbf2/go.mod h1:CJ0aWSM057203Lf6IL+f9T1iT9GByDxfZKAQTCR3kQA= @@ -666,9 +668,5 @@ modernc.org/sqlite v1.38.2/go.mod h1:cPTJYSlgg3Sfg046yBShXENNtPrWrDX8bsbAQBzgQ5E rsc.io/pdf v0.1.1/go.mod h1:n8OzWcQ6Sp37PL01nO98y4iUCRdTGarVfzxY20ICaU4= sourcecraft.dev/bigbes/sr-ht-core v0.0.0-20260718185800-dd418a200152 h1:9kQC+tDO2CO8avlKadb9Z0if4a6vJuEK80+4zcb6/fU= sourcecraft.dev/bigbes/sr-ht-core v0.0.0-20260718185800-dd418a200152/go.mod h1:Mu1Vx39ws/OTKWGoVERXvkdRSPLBdhuFTYv0ftVV31c= -sourcecraft.dev/bigbes/sr-ht-ecore v0.0.0-20260808143603-174115990895 h1:OGZrtBtMoXhyZGXrPqMzmrNQnStoCLBVuegGo7yF1Us= -sourcecraft.dev/bigbes/sr-ht-ecore v0.0.0-20260808143603-174115990895/go.mod h1:KeoZjm+/nnsdtc1WxB7X/0EeC+Rggt2OkwJDEc6XWnw= -sourcecraft.dev/bigbes/sr-ht-ecore v0.0.0-20260808192241-9377c43a02ca h1:LCfxvF1VJl7djl7noAeXObfuY1csJr2OOFExwU4Y/N4= -sourcecraft.dev/bigbes/sr-ht-ecore v0.0.0-20260808192241-9377c43a02ca/go.mod h1:KeoZjm+/nnsdtc1WxB7X/0EeC+Rggt2OkwJDEc6XWnw= sourcecraft.dev/bigbes/sr-ht-ecore v0.0.0-20260808194355-f019dbe4ea3e h1:9yH4eagCWQMdFFbF+LQmvJjXWFdSDijhaxolrwfgatA= sourcecraft.dev/bigbes/sr-ht-ecore v0.0.0-20260808194355-f019dbe4ea3e/go.mod h1:KeoZjm+/nnsdtc1WxB7X/0EeC+Rggt2OkwJDEc6XWnw= diff --git a/remoteapi/credsvc.go b/remoteapi/credsvc.go index 61ff4ebda0d743e3a094c6160dc541d74d7ccf22..ddf0718399017f53942aa502b644f7f1bd722828 100644 --- a/remoteapi/credsvc.go +++ b/remoteapi/credsvc.go @@ -5,19 +5,22 @@ import ( "database/sql" "errors" "fmt" + "log/slog" "net" "strings" - "sourcecraft.dev/bigbes/sr-ht-core/config" - "sourcecraft.dev/bigbes/sr-ht-core/database" remotesapi "github.com/dolthub/dolt/go/gen/proto/dolt/services/remotesapi/v1alpha1" - "github.com/sirupsen/logrus" "github.com/vaughan0/go-ini" "google.golang.org/grpc" "google.golang.org/grpc/codes" "google.golang.org/grpc/metadata" "google.golang.org/grpc/status" + "go.bigb.es/auxilia/scribe" + + "sourcecraft.dev/bigbes/sr-ht-core/config" + "sourcecraft.dev/bigbes/sr-ht-core/database" + "sourcecraft.dev/bigbes/sr-ht-dolt/authn" ) @@ -34,7 +37,7 @@ type credService struct { expectedAud string pool *sql.DB keys authn.KeyStore - logger *logrus.Entry + logger *slog.Logger } // WhoAmI verifies the request's Bearer keypair JWT (exactly as the remotesapi @@ -55,7 +58,7 @@ func (c *credService) WhoAmI(ctx context.Context, _ *remotesapi.WhoAmIRequest) ( if errors.Is(err, authn.ErrInvalidToken) { return nil, status.Error(codes.Unauthenticated, "invalid or expired credentials") } - c.logger.Errorf("credentials WhoAmI backend error: %v", err) + c.logger.ErrorContext(ctx, "WhoAmI backend error", scribe.Err(err)) return nil, status.Error(codes.Unavailable, "authentication temporarily unavailable") } @@ -91,7 +94,7 @@ func bearerToken(ctx context.Context) (string, error) { type CredServer struct { grpc *grpc.Server addr string - logger *logrus.Entry + logger *slog.Logger } // NewCredServer assembles the CredentialsService server. It shares the keystore @@ -104,10 +107,7 @@ func NewCredServer(cfg Config) (*CredServer, error) { if cfg.CredsListenAddr == "" { return nil, fmt.Errorf("remoteapi: NewCredServer requires a CredsListenAddr") } - logger := cfg.Logger - if logger == nil { - logger = logrus.NewEntry(logrus.StandardLogger()) - } + logger := slog.Default().With("component", "credentials") svc := &credService{ conf: cfg.Conf, diff --git a/remoteapi/integration_test.go b/remoteapi/integration_test.go index c109c4732369f1a6cb083b5f33d470c0da06df5a..815bf09ba61e8741a8ad840fc31588d723c9dfd4 100644 --- a/remoteapi/integration_test.go +++ b/remoteapi/integration_test.go @@ -133,8 +133,13 @@ func TestRemoteAPIIntegration(t *testing.T) { // (the bare host) matches what the CLI sends. addr := freeAddr(t) credAddr := freeAddr(t) - logger := logrus.NewEntry(logrus.New()) - logger.Logger.SetLevel(logrus.ErrorLevel) + + // dolt's remotesrv logs every chunk transfer at info; this test moves a + // database, so quiet it down to what a failure needs. It is a logrus entry + // because that is the only shape remotesrv's API accepts — see + // Config.DoltLogger. + doltLogger := logrus.NewEntry(logrus.New()) + doltLogger.Logger.SetLevel(logrus.ErrorLevel) cfg := Config{ Conf: conf, @@ -143,7 +148,7 @@ func TestRemoteAPIIntegration(t *testing.T) { ListenAddr: addr, CredsListenAddr: credAddr, HttpHost: addr, - Logger: logger, + DoltLogger: doltLogger, } srv, err := New(cfg) if err != nil { diff --git a/remoteapi/interceptors.go b/remoteapi/interceptors.go index 60d2342619dc8963b888f8eeb15d2de88c98875d..0d29122dbe234f5b6dd765db8fa7682f6de60033 100644 --- a/remoteapi/interceptors.go +++ b/remoteapi/interceptors.go @@ -5,14 +5,17 @@ import ( "database/sql" "errors" "fmt" + "log/slog" remotesapi "github.com/dolthub/dolt/go/gen/proto/dolt/services/remotesapi/v1alpha1" - "github.com/sirupsen/logrus" "github.com/vaughan0/go-ini" "google.golang.org/grpc" "google.golang.org/grpc/codes" "google.golang.org/grpc/metadata" "google.golang.org/grpc/status" + + "go.bigb.es/auxilia/scribe" + "sourcecraft.dev/bigbes/sr-ht-core/auth" "sourcecraft.dev/bigbes/sr-ht-core/config" "sourcecraft.dev/bigbes/sr-ht-core/database" @@ -87,7 +90,7 @@ type interceptor struct { service string expectedAud string keys authn.KeyStore - logger *logrus.Entry + logger *slog.Logger // pool is the shared database pool, threaded into the request context via // database.Context so db.FromContext-style lookups and the token resolvers @@ -110,13 +113,14 @@ type interceptor struct { // newInterceptor builds the interceptor over the shared pool. It binds a fresh // db.Store per request (the pool owns connection lifetime, ctx bounds each // query). pool and keys must be non-nil. -func newInterceptor(conf ini.File, service, expectedAud string, pool *sql.DB, keys authn.KeyStore, reposRoot string, createStore func(ctx context.Context, absPath string) error, logger *logrus.Entry) *interceptor { +// +// The logger is not a parameter: it is slog's default with this component's +// name on it. Threading one through the constructor was logrus' requirement, +// not this package's — there is no configuration here a caller ever varied. +func newInterceptor(conf ini.File, service, expectedAud string, pool *sql.DB, keys authn.KeyStore, reposRoot string, createStore func(ctx context.Context, absPath string) error) *interceptor { if pool == nil { panic("remoteapi: newInterceptor requires a non-nil *sql.DB") } - if logger == nil { - logger = logrus.NewEntry(logrus.StandardLogger()) - } if createStore == nil { createStore = storage.InitEmptyStore } @@ -125,7 +129,7 @@ func newInterceptor(conf ini.File, service, expectedAud string, pool *sql.DB, ke service: service, expectedAud: expectedAud, keys: keys, - logger: logger, + logger: slog.Default().With("component", "remotesapi.auth"), pool: pool, reposRoot: reposRoot, createStore: createStore, @@ -183,12 +187,12 @@ func (i *interceptor) authenticate(ctx context.Context) (*auth.AuthContext, erro ac, err := authn.ResolveGRPCAuth(ctx, header, i.expectedAud, i.keys) if err != nil { if errors.Is(err, authn.ErrInvalidToken) { - i.logger.Warnf("remotesapi authentication rejected: %v", err) + i.logger.WarnContext(ctx, "authentication rejected", scribe.Err(err)) return nil, status.Error(codes.Unauthenticated, "invalid or expired credentials") } // Transient: meta.sr.ht or the database is unreachable. Never surface as a // hard credential rejection — the client should retry. - i.logger.Errorf("remotesapi authentication backend error: %v", err) + i.logger.ErrorContext(ctx, "authentication backend error", scribe.Err(err)) return nil, status.Error(codes.Unavailable, "authentication temporarily unavailable") } return ac, nil @@ -259,7 +263,8 @@ func (i *interceptor) authorize(ctx context.Context, ac *auth.AuthContext, fullM return nil, err } } else { - i.logger.Errorf("remotesapi repo lookup %s/%s: %v", owner, name, err) + i.logger.ErrorContext(ctx, "repository lookup failed", + "owner", owner, "name", name, scribe.Err(err)) return nil, status.Error(codes.Unavailable, "repository lookup temporarily unavailable") } } @@ -268,7 +273,8 @@ func (i *interceptor) authorize(ctx context.Context, ac *auth.AuthContext, fullM if caller != nil { aclMode, err = store.EffectiveAccess(ctx, caller.UserID, repo.ID) if err != nil { - i.logger.Errorf("remotesapi effective-access user=%d repo=%d: %v", caller.UserID, repo.ID, err) + i.logger.ErrorContext(ctx, "effective-access lookup failed", + "user_id", caller.UserID, "repo_id", repo.ID, scribe.Err(err)) return nil, status.Error(codes.Unavailable, "authorization temporarily unavailable") } } @@ -305,12 +311,14 @@ func (i *interceptor) autoCreate(ctx context.Context, store repoStore, caller *c // Adopt the winner's row; do not touch disk. repo, gerr := store.GetRepoByOwnerAndName(ctx, owner, name) if gerr != nil { - i.logger.Errorf("remotesapi auto-create refetch %s/%s: %v", owner, name, gerr) + i.logger.ErrorContext(ctx, "auto-create refetch failed", + "owner", owner, "name", name, scribe.Err(gerr)) return nil, status.Error(codes.Unavailable, "repository creation temporarily unavailable") } return repo, nil } - i.logger.Errorf("remotesapi auto-create %s/%s: %v", owner, name, cerr) + i.logger.ErrorContext(ctx, "auto-create failed", + "owner", owner, "name", name, scribe.Err(cerr)) return nil, status.Error(codes.Unavailable, "repository creation temporarily unavailable") } @@ -318,9 +326,11 @@ func (i *interceptor) autoCreate(ctx context.Context, store repoStore, caller *c // The row exists but the store does not: roll the row back (best effort) // so the repo does not linger half-created and a retry can succeed. if derr := store.DeleteRepo(ctx, created.ID); derr != nil { - i.logger.Errorf("remotesapi auto-create rollback %s/%s (id=%d): %v", owner, name, created.ID, derr) + i.logger.ErrorContext(ctx, "auto-create rollback failed", + "owner", owner, "name", name, "repo_id", created.ID, scribe.Err(derr)) } - i.logger.Errorf("remotesapi auto-create store %s/%s: %v", owner, name, serr) + i.logger.ErrorContext(ctx, "auto-create store initialization failed", + "owner", owner, "name", name, scribe.Err(serr)) return nil, status.Error(codes.Unavailable, "repository creation temporarily unavailable") } return created, nil diff --git a/remoteapi/interceptors_test.go b/remoteapi/interceptors_test.go index 653000db02dc848595b8ce6af0cbddb520125de8..bab0953b876df7bf6817af8f2b0aee964b8cdbd3 100644 --- a/remoteapi/interceptors_test.go +++ b/remoteapi/interceptors_test.go @@ -3,10 +3,11 @@ package remoteapi import ( "context" "errors" + "io" + "log/slog" "testing" remotesapi "github.com/dolthub/dolt/go/gen/proto/dolt/services/remotesapi/v1alpha1" - "github.com/sirupsen/logrus" "github.com/vaughan0/go-ini" "google.golang.org/grpc" "google.golang.org/grpc/codes" @@ -101,12 +102,19 @@ func (s *stubStore) DeleteRepo(_ context.Context, id int) error { return nil } +// discardLogger is the logger these tests hand the interceptor: the paths under +// test log on their error arms, and a test asserting a gRPC status code has no +// use for the line. +func discardLogger() *slog.Logger { + return slog.New(slog.NewTextHandler(io.Discard, nil)) +} + func testInterceptor(store repoStore) *interceptor { return &interceptor{ conf: ini.File{}, service: "dolt.sr.ht", expectedAud: "dolt.srht.bigb.es", - logger: logrus.NewEntry(logrus.New()), + logger: discardLogger(), stores: func() repoStore { return store }, reposRoot: "/tmp/repos", createStore: func(context.Context, string) error { return nil }, @@ -449,7 +457,7 @@ func TestUnaryAnonymous(t *testing.T) { i := &interceptor{ conf: ini.File{}, service: "dolt.sr.ht", - logger: logrus.NewEntry(logrus.New()), + logger: discardLogger(), stores: func() repoStore { return &stubStore{repo: repo(1, 100, core.VisibilityPublic)} }, } var gotCaller bool diff --git a/remoteapi/server.go b/remoteapi/server.go index b78d0fb36febdc816bc7da29083a25f144ebd674..15b7ffc1cc5e63502698b4b0fa3a68e56b9233d6 100644 --- a/remoteapi/server.go +++ b/remoteapi/server.go @@ -4,6 +4,7 @@ import ( "context" "database/sql" "fmt" + "log/slog" "net" remotesapi "github.com/dolthub/dolt/go/gen/proto/dolt/services/remotesapi/v1alpha1" @@ -12,6 +13,8 @@ import ( "github.com/sirupsen/logrus" "github.com/vaughan0/go-ini" + "go.bigb.es/auxilia/scribe" + "sourcecraft.dev/bigbes/sr-ht-dolt/db" "sourcecraft.dev/bigbes/sr-ht-dolt/storage" ) @@ -48,8 +51,11 @@ type Config struct { // chunk URLs (auth then cannot be host-checked; used only by tests without a // stable host). HttpHost string - // Logger is the base logger; may be nil (a default is used). - Logger *logrus.Entry + // DoltLogger is the logger dolt's own remotesrv writes through. It exists + // only because that API takes a *logrus.Entry and nothing else; everything + // this package logs itself goes through slog's default. nil lets remotesrv + // install logrus' standard logger, which is what it did before. + DoltLogger *logrus.Entry } // Server is the assembled remotesapi server: the remotesrv chunk-store server @@ -58,7 +64,7 @@ type Config struct { type Server struct { srv *remotesrv.Server cache *storage.Cache - logger *logrus.Entry + logger *slog.Logger addr string } @@ -72,10 +78,7 @@ func New(cfg Config) (*Server, error) { if cfg.ReposRoot == "" { return nil, fmt.Errorf("remoteapi: New requires a ReposRoot") } - logger := cfg.Logger - if logger == nil { - logger = logrus.NewEntry(logrus.StandardLogger()) - } + logger := slog.Default().With("component", "remotesapi") // Repo lookup: resolve owner/name to the absolute on-disk store dir via the // repository row. By the time Cache.Get runs, the row already exists: the @@ -93,7 +96,7 @@ func New(cfg Config) (*Server, error) { cache := storage.NewCache(lookup) keys := newKeyStore(cfg.DB) - icept := newInterceptor(cfg.Conf, serviceName, normalizeAud(cfg.HttpHost), cfg.DB, keys, cfg.ReposRoot, storage.InitEmptyStore, logger) + icept := newInterceptor(cfg.Conf, serviceName, normalizeAud(cfg.HttpHost), cfg.DB, keys, cfg.ReposRoot, storage.InitEmptyStore) // Load-bearing (see storage/init.go): the FS MUST be rooted at ReposRoot via // LocalFilesysWithWorkingDir so sealed chunk-download URLs carry clean @@ -105,7 +108,7 @@ func New(cfg Config) (*Server, error) { } srv, err := remotesrv.NewServer(remotesrv.ServerArgs{ - Logger: logger, + Logger: cfg.DoltLogger, HttpHost: cfg.HttpHost, HttpListenAddr: cfg.ListenAddr, GrpcListenAddr: cfg.ListenAddr, // == HttpListenAddr ⇒ single h2c port @@ -117,7 +120,7 @@ func New(cfg Config) (*Server, error) { }) if err != nil { if cerr := cache.Close(); cerr != nil { - logger.Warnf("remoteapi: closing cache after NewServer failure: %v", cerr) + logger.Warn("closing the chunk-store cache after a NewServer failure", scribe.Err(cerr)) } return nil, fmt.Errorf("remoteapi: remotesrv.NewServer: %w", err) } @@ -145,7 +148,7 @@ func (s *Server) Serve() error { func (s *Server) GracefulStop() { s.srv.GracefulStop() if err := s.cache.Close(); err != nil { - s.logger.Warnf("remoteapi: closing cache on shutdown: %v", err) + s.logger.Warn("closing the chunk-store cache on shutdown", scribe.Err(err)) } } diff --git a/web/templates.go b/web/templates.go index a9079e2852e69946378125990fd039cba56d975a..ece9dd9622d3ed8b85658b6acb0bdaf663b219b8 100644 --- a/web/templates.go +++ b/web/templates.go @@ -5,11 +5,13 @@ import ( "fmt" "html/template" "io/fs" - "log" + "log/slog" "net/http" "net/url" "strings" + "go.bigb.es/auxilia/scribe" + "sourcecraft.dev/bigbes/sr-ht-ecore/pages" ) @@ -140,6 +142,7 @@ func humanizeSize(n uint64) string { // do with it here but say so. func (a *app) render(w http.ResponseWriter, status int, page string, data any) { if err := a.pages.Render(w, status, page, data); err != nil { - log.Printf("web: %v", err) + slog.Error("rendering a page failed", + "component", "web", "page", page, "status", status, scribe.Err(err)) } }