~bigbes/sr-ht-spec

643fa0b5d34a047923791d23f11ab585dd7487d5 — Eugene Blikh 9 days ago 3a56ee6
logging: log through slog and scribe rather than stdlib log

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.
M authn/resolver.go => authn/resolver.go +6 -2
@@ 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

M cmd/specsrht/main.go => cmd/specsrht/main.go +29 -0
@@ 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)`, "***"),
	))
}


M web/diff.go => web/diff.go +5 -2
@@ 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(`<tr class="ph-notes`)

M web/handlers.go => web/handlers.go +16 -8
@@ 5,11 5,12 @@ import (
	"errors"
	"fmt"
	"html/template"
	"log"
	"log/slog"
	"net/http"
	"strings"

	"github.com/go-chi/chi/v5"
	"go.bigb.es/auxilia/scribe"
	"sourcecraft.dev/bigbes/sr-ht-ecore/chrome"

	"sourcecraft.dev/bigbes/sr-ht-spec/authn"


@@ 149,7 150,8 @@ func httpStatusFor(err error) int {
func (s *Server) fail(w http.ResponseWriter, r *http.Request, err error) {
	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 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))
	}
}


M web/inbox.go => web/inbox.go +5 -2
@@ 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))
	}
}


M web/proposal.go => web/proposal.go +4 -2
@@ 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))
	}
}


M web/server.go => web/server.go +3 -3
@@ 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 <link>, so an unstyled build stays a presentation failure.

M web/templates.go => web/templates.go +4 -2
@@ 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))
	}
}