From 643fa0b5d34a047923791d23f11ab585dd7487d5 Mon Sep 17 00:00:00 2001 From: Eugene Blikh Date: Sat, 8 Aug 2026 22:56:49 +0300 Subject: [PATCH] logging: log through slog and scribe rather than stdlib log MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit sr-ht-ecore's panic middleware now reports through log/slog, and it reports through the *default* logger — nothing can hand a middleware in another module this service's *slog.Logger. So the daemon's scribe handler becomes the one install point, and the packages that were still calling log.Printf go through the default logger too: the read plane's render and encode failures, its 5xx mapping, and the credential resolver's fail-closed line. Each carries the fields that used to be interpolated into the sentence — method, path, status, page, doc — and the error itself through scribe.Err. The handler grows what it was missing: file:line, because most of what reaches it is a failure and 'which of the six render sites' is the first question; colour dropped when stderr is not a terminal; and the masks. This daemon handles the unified-login cookie and tokens.sr.ht working tokens, and a struct logged whole is how a live credential outlives its own request in a log file — masking in the handler covers the log line nobody reviewed as well as these. cmd/specsrht-migrate keeps stdlib log on purpose: it is a one-shot CLI whose 'specsrht-migrate: ...' progress an operator reads at the terminal during an upgrade, and log.Fatalf is its error exit. --- authn/resolver.go | 8 ++++++-- cmd/specsrht/main.go | 29 +++++++++++++++++++++++++++++ web/diff.go | 7 +++++-- web/handlers.go | 24 ++++++++++++++++-------- web/inbox.go | 7 +++++-- web/proposal.go | 6 ++++-- web/server.go | 6 +++--- web/templates.go | 6 ++++-- 8 files changed, 72 insertions(+), 21 deletions(-) diff --git a/authn/resolver.go b/authn/resolver.go index 22bc886e46846d37bedd0a6fb6b8d428c2fca194..210b9af647fa2adacddd0a16daa4b0bc20a439aa 100644 --- a/authn/resolver.go +++ b/authn/resolver.go @@ -3,10 +3,12 @@ package authn import ( "context" "fmt" - "log" + "log/slog" "net/http" "strings" + "go.bigb.es/auxilia/scribe" + "sourcecraft.dev/bigbes/sr-ht-spec/core" ) @@ -177,7 +179,9 @@ func (rs *Resolver) Middleware() func(http.Handler) http.Handler { // anonymous — would turn a Postgres blip or an unreachable // tokens.sr.ht into agents silently losing their write // access. - log.Printf("authn: resolving bearer credential: %v", err) + slog.ErrorContext(r.Context(), "resolving an agent credential failed", + "method", r.Method, "path", r.URL.Path, "status", status, + scribe.Err(err)) } http.Error(w, resolveFailureMessage(status), status) return diff --git a/cmd/specsrht/main.go b/cmd/specsrht/main.go index cdb6e49d81e918bfcc0dc75967dead01a1c08390..de57cc505efaa4879dff226368d4f313219be230 100644 --- a/cmd/specsrht/main.go +++ b/cmd/specsrht/main.go @@ -233,12 +233,41 @@ 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( 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)`, "***"), )) } diff --git a/web/diff.go b/web/diff.go index 796d9987272f3a61d658c8f524f286d1e5ca9b5f..50dd78f7bec68ba324fd27183daf9557e910cbf9 100644 --- a/web/diff.go +++ b/web/diff.go @@ -6,9 +6,11 @@ import ( "encoding/hex" "fmt" "html/template" - "log" + "log/slog" "strings" + "go.bigb.es/auxilia/scribe" + "sourcecraft.dev/bigbes/sr-ht-spec/core" "sourcecraft.dev/bigbes/sr-ht-spec/prosediff" "sourcecraft.dev/bigbes/sr-ht-spec/service" @@ -343,7 +345,8 @@ func (r *docRenderer) writeNotesRow(b *strings.Builder, row diffRow) { var buf bytes.Buffer if err := blockThreadsTmpl.Execute(&buf, data); err != nil { - log.Printf("web: rendering comments on %s: %v", r.in.Path, err) + slog.Error("rendering the comments on a diff block failed", + "doc", r.in.Path, scribe.Err(err)) return } b.WriteString(`= 500 { - log.Printf("web: %s: %v", r.URL.Path, err) + slog.ErrorContext(r.Context(), "the read plane could not answer a request", + "method", r.Method, "path", r.URL.Path, "status", status, scribe.Err(err)) s.renderError(w, r, status, "") return } @@ -165,7 +167,8 @@ func (s *Server) failFormat(w http.ResponseWriter, r *http.Request, f format, er } status := httpStatusFor(err) if status >= 500 { - log.Printf("web: %s: %v", r.URL.Path, err) + slog.ErrorContext(r.Context(), "the read plane could not answer a machine request", + "method", r.Method, "path", r.URL.Path, "status", status, scribe.Err(err)) http.Error(w, "internal server error", status) return } @@ -216,7 +219,8 @@ func (s *Server) handleIndex(w http.ResponseWriter, r *http.Request) { } vd.Data = data if err := s.pages.Render(w, http.StatusOK, "index", vd); err != nil { - log.Printf("web: render the landing page for %s: %v", r.URL.Path, err) + slog.ErrorContext(r.Context(), "rendering a page failed after it was answered", + "page", "index", "path", r.URL.Path, scribe.Err(err)) } } @@ -270,7 +274,8 @@ func (s *Server) handleSpace(w http.ResponseWriter, r *http.Request) { Items: flattenTree(snap, revQuery(rev)), } if err := s.pages.Render(w, http.StatusOK, "space", vd); err != nil { - log.Printf("web: render the space page for %s: %v", r.URL.Path, err) + slog.ErrorContext(r.Context(), "rendering a page failed after it was answered", + "page", "space", "path", r.URL.Path, scribe.Err(err)) } } @@ -485,7 +490,8 @@ func (s *Server) handleDocument(w http.ResponseWriter, r *http.Request) { enc := json.NewEncoder(w) enc.SetIndent("", " ") if err := enc.Encode(payload); err != nil { - log.Printf("web: encoding %s.json: %v", docPath, err) + slog.ErrorContext(r.Context(), "encoding a document as JSON failed mid-response", + "doc", docPath, scribe.Err(err)) } return } @@ -530,7 +536,8 @@ func (s *Server) handleDocument(w http.ResponseWriter, r *http.Request) { vd := s.view(r, page.Title+" — "+ref.String()) vd.Data = data if err := s.pages.Render(w, http.StatusOK, "document", vd); err != nil { - log.Printf("web: render the document page for %s: %v", r.URL.Path, err) + slog.ErrorContext(r.Context(), "rendering a page failed after it was answered", + "page", "document", "path", r.URL.Path, scribe.Err(err)) } } @@ -647,7 +654,8 @@ func (s *Server) handleSearch(w http.ResponseWriter, r *http.Request) { vd.Title = "search — " + vd.SiteName + " " + vd.SiteLabel vd.Data = data if err := s.pages.Render(w, http.StatusOK, "search", vd); err != nil { - log.Printf("web: render the search page for %s: %v", r.URL.Path, err) + slog.ErrorContext(r.Context(), "rendering a page failed after it was answered", + "page", "search", "path", r.URL.Path, scribe.Err(err)) } } diff --git a/web/inbox.go b/web/inbox.go index f67a387522dae6e95bdd4d8ee35bc84a8d3242cf..d953f7c041a45c6f8c3bf4a41f7fe7302533349e 100644 --- a/web/inbox.go +++ b/web/inbox.go @@ -1,11 +1,13 @@ package web import ( - "log" + "log/slog" "net/http" "strconv" "time" + "go.bigb.es/auxilia/scribe" + "sourcecraft.dev/bigbes/sr-ht-spec/authn" "sourcecraft.dev/bigbes/sr-ht-spec/service" ) @@ -72,7 +74,8 @@ func (s *Server) handleInbox(w http.ResponseWriter, r *http.Request) { NewCount: newCount, } if err := s.pages.Render(w, http.StatusOK, "inbox", vd); err != nil { - log.Printf("web: render the inbox page for %s: %v", r.URL.Path, err) + slog.ErrorContext(r.Context(), "rendering a page failed after it was answered", + "page", "inbox", "path", r.URL.Path, scribe.Err(err)) } } diff --git a/web/proposal.go b/web/proposal.go index 625a0f7ea014ddc8e159ec1a35c2e6c26e87cdfe..9ec107eaa6c7ae94da4c42164d32c167a8037fc6 100644 --- a/web/proposal.go +++ b/web/proposal.go @@ -3,11 +3,12 @@ package web import ( "context" "fmt" - "log" + "log/slog" "net/http" "strconv" "github.com/go-chi/chi/v5" + "go.bigb.es/auxilia/scribe" "sourcecraft.dev/bigbes/sr-ht-spec/authn" "sourcecraft.dev/bigbes/sr-ht-spec/core" @@ -172,7 +173,8 @@ func (s *Server) handleProposal(w http.ResponseWriter, r *http.Request) { Unresolved: unresolvedThreads(threads), } if err := s.pages.Render(w, http.StatusOK, "proposal", vd); err != nil { - log.Printf("web: render the proposal page for %s: %v", r.URL.Path, err) + slog.ErrorContext(r.Context(), "rendering a page failed after it was answered", + "page", "proposal", "proposal_id", p.ID, "path", r.URL.Path, scribe.Err(err)) } } diff --git a/web/server.go b/web/server.go index 3676829236a629199116ce70a705ccd5af4476ad..af0ba42e45dba809b9b0b8b3794a40938f8efde3 100644 --- a/web/server.go +++ b/web/server.go @@ -83,7 +83,7 @@ package web import ( "fmt" "io/fs" - "log" + "log/slog" "net/http" "github.com/vaughan0/go-ini" @@ -199,8 +199,8 @@ func New(opts Options) (*Server, error) { return nil, fmt.Errorf("web: %w", err) } if cssHref == "" { - log.Printf("web: no main.min.*.css embedded in this binary — pages will " + - "render unstyled; run `make css` before `go build`") + slog.Warn("no stylesheet is embedded in this binary, so pages will render unstyled", + "glob", "static/main.min.*.css", "remedy", "run `make css` before `go build`") } // chrome.Page renders a bare page for an empty StyleHref rather than an // empty , so an unstyled build stays a presentation failure. diff --git a/web/templates.go b/web/templates.go index 9ef8bbd911d06ea4bad7d8eeb4d5e4fa2434c956..eff6a47c46ba8061810393996546fb76c308eb06 100644 --- a/web/templates.go +++ b/web/templates.go @@ -3,10 +3,11 @@ package web import ( "embed" "html/template" - "log" + "log/slog" "net/http" "strings" + "go.bigb.es/auxilia/scribe" "sourcecraft.dev/bigbes/sr-ht-ecore/chrome" "sourcecraft.dev/bigbes/sr-ht-ecore/pages" ) @@ -83,6 +84,7 @@ func (s *Server) renderError(w http.ResponseWriter, r *http.Request, status int, vd := s.view(r, http.StatusText(status)) vd.Data = pages.Error(status, message) if err := s.pages.Render(w, status, pages.ErrorPage, vd); err != nil { - log.Printf("web: render the %d page for %s %s: %v", status, r.Method, r.URL.Path, err) + slog.ErrorContext(r.Context(), "rendering the error page failed after it was answered", + "status", status, "method", r.Method, "path", r.URL.Path, scribe.Err(err)) } }