~bigbes/sr-ht-ecore

f019dbe4ea3ebbac42ad4ce864dd349f7e569909 — Eugene Blikh 9 days ago 9377c43
middleware: report panics through slog

The two log.Printf lines were the last stdlib log in ecore, and they printed
a formatted sentence where every service on the instance now emits structured
records — a panic report that cannot be filtered by path or grouped by route
is the one log line an operator most wants to query.

Through slog's default logger rather than one handed to RecoverPanics: a
library has no business choosing a handler. The service installs scribe's at
startup with SetDefault, and these land in the same stream, with the same
masking, as its own lines.
4 files changed, 48 insertions(+), 23 deletions(-)

M assets/assets.go
M middleware/middleware.go
M middleware/middleware_test.go
M pages/pages.go
M assets/assets.go => assets/assets.go +1 -1
@@ 21,7 21,7 @@
//		return nil, err
//	}
//	if cssHref == "" {
//		log.Printf("web: no stylesheet in this binary; run `make css` before `go build`")
//		slog.Warn("no stylesheet in this binary; run `make css` before `go build`")
//	}
//	svc.StyleHref = cssHref // "" renders a bare page — see Resolve
//

M middleware/middleware.go => middleware/middleware.go +20 -5
@@ 27,13 27,21 @@
// on it — so hoisting it would put a router dependency in a package whose whole
// point is that it needs nothing but net/http. It stays in each service, where
// the router it talks to already is.
//
// Panics are reported through slog's default logger rather than a logger this
// package is handed. A library has no business choosing a handler: the service
// installs its own — scribe's tinted one on this instance — with
// slog.SetDefault at startup, and everything logged here lands in the same
// stream, with the same masking rules, as the service's own lines. Handing a
// *slog.Logger to RecoverPanics would buy configurability nobody wants and cost
// every caller a parameter.
package middleware

import (
	"bufio"
	"errors"
	"io"
	"log"
	"log/slog"
	"net"
	"net/http"
	"runtime/debug"


@@ 181,8 189,11 @@ func RecoverPanics(render func(w http.ResponseWriter, r *http.Request, recovered
				if err, ok := recovered.(error); ok && errors.Is(err, http.ErrAbortHandler) {
					panic(recovered)
				}
				log.Printf("middleware: panic serving %s %s: %v\n%s",
					r.Method, r.URL.Path, recovered, debug.Stack())
				slog.ErrorContext(r.Context(), "panic serving a request",
					"method", r.Method,
					"path", r.URL.Path,
					"panic", recovered,
					"stack", string(debug.Stack()))
				if tracked.started {
					// Half a page is already out. There is no status line left
					// to send and nothing useful to append; abandon the


@@ 220,8 231,12 @@ func renderOnce(
		if err, ok := second.(error); ok && errors.Is(err, http.ErrAbortHandler) {
			panic(second)
		}
		log.Printf("middleware: panic rendering the error page for %s %s: %v (original panic: %v)\n%s",
			r.Method, r.URL.Path, second, recovered, debug.Stack())
		slog.ErrorContext(r.Context(), "panic rendering the error page",
			"method", r.Method,
			"path", r.URL.Path,
			"panic", second,
			"original_panic", recovered,
			"stack", string(debug.Stack()))
		panic(http.ErrAbortHandler)
	}()
	render(w, r, recovered)

M middleware/middleware_test.go => middleware/middleware_test.go +25 -16
@@ 2,31 2,35 @@ package middleware

import (
	"bytes"
	"log"
	"log/slog"
	"net"
	"net/http"
	"net/http/httptest"
	"os"
	"testing"

	"github.com/stretchr/testify/assert"
	"github.com/stretchr/testify/require"
)

// captureLog redirects the standard logger into a buffer for the duration of one
// test, both to keep the panic stacks out of the test output and so that a test
// can assert on what an operator would have seen.
// captureLog redirects the default slog logger into a buffer for the duration
// of one test, both to keep the panic stacks out of the test output and so that
// a test can assert on what an operator would have seen.
func captureLog(t *testing.T) *bytes.Buffer {
	t.Helper()

	var buf bytes.Buffer
	flags := log.Flags()
	log.SetOutput(&buf)
	log.SetFlags(0)
	t.Cleanup(func() {
		log.SetOutput(os.Stderr)
		log.SetFlags(flags)
	})
	previous := slog.Default()
	slog.SetDefault(slog.New(slog.NewTextHandler(&buf, &slog.HandlerOptions{
		Level: slog.LevelDebug,
		// Drop the timestamp so an assertion can match a whole line.
		ReplaceAttr: func(_ []string, a slog.Attr) slog.Attr {
			if a.Key == slog.TimeKey {
				return slog.Attr{}
			}
			return a
		},
	})))
	t.Cleanup(func() { slog.SetDefault(previous) })

	return &buf
}


@@ 119,7 123,9 @@ func TestRecoverPanicsRendersTheErrorPageAndAnswers500(t *testing.T) {
	assert.Contains(t, rec.Body.String(), "Something went wrong.")

	// The detail goes to the log, with the request around it and a stack.
	assert.Contains(t, logged.String(), "panic serving GET /tokens: the store is nil")
	assert.Contains(t, logged.String(), `msg="panic serving a request"`)
	assert.Contains(t, logged.String(), "method=GET path=/tokens")
	assert.Contains(t, logged.String(), `panic="the store is nil"`)
	assert.Contains(t, logged.String(), "runtime/debug.Stack")
	assert.NotContains(t, rec.Body.String(), "the store is nil", "never to the viewer")
}


@@ 160,7 166,9 @@ func TestRecoverPanicsAbandonsAResponseThatHasStarted(t *testing.T) {
	assert.False(t, rendered, "there is no status line left to render a page over")
	assert.Equal(t, http.StatusOK, rec.Code, "the status already sent is not rewritten")
	assert.Equal(t, "<html>half a p", rec.Body.String(), "nothing is appended to the truncated body")
	assert.Contains(t, logged.String(), "panic serving GET /repos: template died mid-page")
	assert.Contains(t, logged.String(), `msg="panic serving a request"`)
	assert.Contains(t, logged.String(), "method=GET path=/repos")
	assert.Contains(t, logged.String(), `panic="template died mid-page"`)
}

func TestRecoverPanicsCountsAFlushAsAStartedResponse(t *testing.T) {


@@ 211,8 219,9 @@ func TestRecoverPanicsDoesNotLoopWhenTheErrorPagePanics(t *testing.T) {
	})

	assert.Equal(t, 1, calls, "the error page is attempted exactly once")
	assert.Contains(t, logged.String(), "panic rendering the error page for GET /tokens: the chrome is broken too")
	assert.Contains(t, logged.String(), "original panic: the store is nil")
	assert.Contains(t, logged.String(), `msg="panic rendering the error page"`)
	assert.Contains(t, logged.String(), `panic="the chrome is broken too"`)
	assert.Contains(t, logged.String(), `original_panic="the store is nil"`)
}

func TestRecoverPanicsForwardsErrAbortHandlerFromTheErrorPage(t *testing.T) {

M pages/pages.go => pages/pages.go +2 -1
@@ 32,7 32,8 @@
// and in a handler:
//
//	if err := s.pages.Render(w, http.StatusOK, "index", vd); err != nil {
//		log.Printf("web: %s %s: %v", r.Method, r.URL.Path, err)
//		slog.ErrorContext(r.Context(), "render failed",
//			"method", r.Method, "path", r.URL.Path, scribe.Err(err))
//	}
//
// Render answers the response itself in every case, so a returned error is for