tsweb: log once per request

StdHandler/retHandler would previously emit one log line for each request.
If there were multiple StdHandler in the chain, there would be one log line
per instance of retHandler.

With this change, only the outermost StdHandler/logHandler actually logs the
request or invokes OnStart or OnCompletion callbacks. The error-rendering part
of retHandler lives on in errorHandler, and errorHandler passes those errors up
the stack to logHandler through a callback that logHandler places in the
request.Context().

Updates tailscale/corp#19999

Signed-off-by: Paul Scott <paul@tailscale.com>

tsweb/tsweb.go

@@ -12,6 +12,7 @@
 	"errors"
 	"expvar"
 	"fmt"
+	"io"
 	"net"
 	"net/http"
 	_ "net/http/pprof"
@@ -32,6 +33,7 @@
 	"tailscale.com/net/tsaddr"
 	"tailscale.com/tsweb/varz"
 	"tailscale.com/types/logger"
+	"tailscale.com/util/ctxkey"
 	"tailscale.com/util/vizerror"
 )
 
@@ -233,6 +235,8 @@ func (o *BucketedStatsOptions) bucketForRequest(r *http.Request) string {
 	return NormalizedPath(r.URL.Path)
 }
 
+// HandlerOptions are options used by [StdHandler], containing both [LogOptions]
+// used by [LogHandler] and [ErrorOptions] used by [ErrorHandler].
 type HandlerOptions struct {
 	QuietLoggingIfSuccessful bool // if set, do not log successfully handled HTTP requests (200 and 304 status codes)
 	Logf                     logger.Logf
@@ -264,6 +268,87 @@ type HandlerOptions struct {
 	OnCompletion OnCompletionFunc
 }
 
+// LogOptions are the options used by [LogHandler].
+// These options are a subset of [HandlerOptions].
+type LogOptions struct {
+	// Logf is used to log HTTP requests and responses.
+	Logf logger.Logf
+	// Now is a function giving the current time. Defaults to [time.Now].
+	Now func() time.Time
+
+	// QuietLoggingIfSuccessful suppresses logging of handled HTTP requests
+	// where the request's response status code is 200 or 304.
+	QuietLoggingIfSuccessful bool
+
+	// StatusCodeCounters maintains counters of status code classes.
+	// The keys are "1xx", "2xx", "3xx", "4xx", and "5xx".
+	// If nil, no counting is done.
+	StatusCodeCounters *expvar.Map
+	// StatusCodeCountersFull maintains counters of status codes.
+	// The keys are HTTP numeric response codes e.g. 200, 404, ...
+	// If nil, no counting is done.
+	StatusCodeCountersFull *expvar.Map
+	// BucketedStats computes and exposes statistics for each bucket based on
+	// the contained parameters. If nil, no counting is done.
+	BucketedStats *BucketedStatsOptions
+
+	// OnStart is called inline before ServeHTTP is called. Optional.
+	OnStart OnStartFunc
+	// OnCompletion is called inline when ServeHTTP is finished and gets
+	// useful data that the implementor can use for metrics. Optional.
+	OnCompletion OnCompletionFunc
+}
+
+func (o HandlerOptions) logOptions() LogOptions {
+	return LogOptions{
+		QuietLoggingIfSuccessful: o.QuietLoggingIfSuccessful,
+		Logf:                     o.Logf,
+		Now:                      o.Now,
+		StatusCodeCounters:       o.StatusCodeCounters,
+		StatusCodeCountersFull:   o.StatusCodeCountersFull,
+		BucketedStats:            o.BucketedStats,
+		OnStart:                  o.OnStart,
+		OnCompletion:             o.OnCompletion,
+	}
+}
+
+func (opts LogOptions) withDefaults() LogOptions {
+	if opts.Logf == nil {
+		opts.Logf = logger.Discard
+	}
+	if opts.Now == nil {
+		opts.Now = time.Now
+	}
+	return opts
+}
+
+// ErrorOptions are options used by [ErrorHandler].
+type ErrorOptions struct {
+	// Logf is used to record unexpected behaviours when returning HTTPError but
+	// different error codes have already been written to the client.
+	Logf logger.Logf
+	// OnError is called if the handler returned a HTTPError. This
+	// is intended to be used to present pretty error pages if
+	// the user agent is determined to be a browser.
+	OnError ErrorHandlerFunc
+}
+
+func (opts ErrorOptions) withDefaults() ErrorOptions {
+	if opts.Logf == nil {
+		opts.Logf = logger.Discard
+	}
+	if opts.OnError == nil {
+		opts.OnError = writeHTTPError
+	}
+	return opts
+}
+
+func (opts HandlerOptions) errorOptions() ErrorOptions {
+	return ErrorOptions{
+		OnError: opts.OnError,
+	}
+}
+
 // ErrorHandlerFunc is called to present a error response.
 type ErrorHandlerFunc func(http.ResponseWriter, *http.Request, HTTPError)
 
@@ -294,25 +379,47 @@ func (f ReturnHandlerFunc) ServeHTTPReturn(w http.ResponseWriter, r *http.Reques
 
 // StdHandler converts a ReturnHandler into a standard http.Handler.
 // Handled requests are logged using opts.Logf, as are any errors.
-// Errors are handled as specified by the Handler interface.
+// Errors are handled as specified by the ReturnHandler interface.
+// Short-hand for LogHandler(ErrorHandler()).
 func StdHandler(h ReturnHandler, opts HandlerOptions) http.Handler {
-	if opts.Now == nil {
-		opts.Now = time.Now
-	}
-	if opts.Logf == nil {
-		opts.Logf = logger.Discard
-	}
-	return retHandler{h, opts}
+	return LogHandler(ErrorHandler(h, opts.errorOptions()), opts.logOptions())
 }
 
-// retHandler is an http.Handler that wraps a Handler and handles errors.
-type retHandler struct {
-	rh   ReturnHandler
-	opts HandlerOptions
+// LogHandler returns an http.Handler that logs to opts.Logf.
+// It logs both successful and failing requests.
+// The log line includes the first error returned to [Handler] within.
+// The outer-most LogHandler(LogHandler(...)) does all of the logging.
+// Inner LogHandler instance do nothing.
+func LogHandler(h http.Handler, opts LogOptions) http.Handler {
+	return logHandler{h, opts.withDefaults()}
 }
 
-// ServeHTTP implements the http.Handler interface.
-func (h retHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
+// ErrorHandler converts a [ReturnHandler] into a standard [http.Handler].
+// Errors are handled as specified by the [ReturnHandler.ServeHTTPReturn] method.
+func ErrorHandler(h ReturnHandler, opts ErrorOptions) http.Handler {
+	return errorHandler{h, opts.withDefaults()}
+}
+
+// errCallback is added to logHandler's request context so that errorHandler can
+// pass errors back up the stack to logHandler.
+var errCallback = ctxkey.New[func(string)]("tailscale.com/tsweb.errCallback", nil)
+
+// logHandler is a http.Handler which logs the HTTP request.
+// It injects an errCallback for errorHandler to augment the log message with
+// a specific error.
+type logHandler struct {
+	h    http.Handler
+	opts LogOptions
+}
+
+func (h logHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
+	// If there's already a logHandler up the chain, skip this one.
+	ctx := r.Context()
+	if errCallback.Has(ctx) {
+		h.h.ServeHTTP(w, r)
+		return
+	}
+
 	msg := AccessLogRecord{
 		Time:       h.opts.Now(),
 		RemoteAddr: r.RemoteAddr,
@@ -347,16 +454,25 @@ func (h retHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		fn(r, msg)
 	}
 
+	// Let errorHandler tell us what error it wrote to the client.
+	r = r.WithContext(errCallback.WithValue(ctx, func(e string) {
+		if ctx.Err() == context.Canceled {
+			msg.Code = 499 // nginx convention: Client Closed Request
+			msg.Err = context.Canceled.Error()
+			return
+		}
+		if msg.Err != "" {
+			return
+		}
+		msg.Err = e
+	}))
+
 	lw := &loggingResponseWriter{ResponseWriter: w, logf: h.opts.Logf}
 
-	// In case the handler panics, we want to recover and continue logging the
-	// error before raising the panic again for the server to handle.
-	var (
-		didPanic bool
-		panicRes any
-	)
+	// Invoke the handler that we're logging.
+	var recovered any
 	defer func() {
-		if didPanic {
+		if recovered != nil {
 			// TODO(icio): When the panic below is eventually caught by
 			// http.Server, it cancels the inlight request and the "500 Internal
 			// Server Error" response we wrote to the client below is never
@@ -364,113 +480,41 @@ func (h retHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 			if f, ok := w.(http.Flusher); ok {
 				f.Flush()
 			}
-			panic(panicRes)
+			panic(recovered)
 		}
 	}()
-	runWithPanicProtection := func() (err error) {
+	func() {
 		defer func() {
-			if r := recover(); r != nil {
-				didPanic = true
-				panicRes = r
-				if r == http.ErrAbortHandler {
-					err = http.ErrAbortHandler
-				} else {
-					// Even if r is an error, do not wrap it as an error here as
-					// that would allow things like panic(vizerror.New("foo")) which
-					// is really hard to define the behavior of.
-					var stack [10000]byte
-					n := runtime.Stack(stack[:], false)
-					err = fmt.Errorf("panic: %v\n\n%s", r, stack[:n])
-				}
-			}
+			recovered = recover()
+		}()
+		h.h.ServeHTTP(lw, r)
 	}()
-		return h.rh.ServeHTTPReturn(lw, r)
-	}
-	err := runWithPanicProtection()
 
-	var hErr HTTPError
-	var hErrOK bool
-	if errors.As(err, &hErr) {
-		hErrOK = true
-	} else if vizErr, ok := vizerror.As(err); ok {
-		hErrOK = true
-		hErr = HTTPError{Msg: vizErr.Error()}
-	}
-
-	if lw.code == 0 && err == nil && !lw.hijacked {
-		// If the handler didn't write and didn't send a header, that still means 200.
-		// (See https://play.golang.org/p/4P7nx_Tap7p)
-		lw.code = 200
-	}
-
-	msg.Seconds = h.opts.Now().Sub(msg.Time).Seconds()
-	msg.Code = lw.code
+	// Complete our access log from the loggingResponseWriter.
 	msg.Bytes = lw.bytes
-
+	msg.Seconds = h.opts.Now().Sub(msg.Time).Seconds()
 	switch {
 	case lw.hijacked:
 		// Connection no longer belongs to us, just log that we
 		// switched protocols away from HTTP.
-		if msg.Code == 0 {
 		msg.Code = http.StatusSwitchingProtocols
+	case lw.code == 0:
+		// If the handler didn't write and didn't send a header, that still means 200.
+		// (See https://play.golang.org/p/4P7nx_Tap7p)
+		msg.Code = 200
+	default:
+		msg.Code = lw.code
 	}
-	case err != nil && r.Context().Err() == context.Canceled:
-		msg.Code = 499 // nginx convention: Client Closed Request
-		msg.Err = context.Canceled.Error()
-	case hErrOK:
-		// Handler asked us to send an error. Do so, if we haven't
-		// already sent a response.
-		msg.Err = hErr.Msg
-		if hErr.Err != nil {
-			if msg.Err == "" {
-				msg.Err = hErr.Err.Error()
-			} else {
-				msg.Err = msg.Err + ": " + hErr.Err.Error()
-			}
-		}
-		if lw.code != 0 {
-			h.opts.Logf("[unexpected] handler returned HTTPError %v, but already sent a response with code %d", hErr, lw.code)
-			break
-		}
-		msg.Code = hErr.Code
-		if msg.Code == 0 {
-			h.opts.Logf("[unexpected] HTTPError %v did not contain an HTTP status code, sending internal server error", hErr)
-			msg.Code = http.StatusInternalServerError
-		}
-		if h.opts.OnError != nil {
-			h.opts.OnError(lw, r, hErr)
-		} else {
-			// Default headers set by http.Error.
-			lw.Header().Set("Content-Type", "text/plain; charset=utf-8")
-			lw.Header().Set("X-Content-Type-Options", "nosniff")
-			for k, vs := range hErr.Header {
-				lw.Header()[k] = vs
-			}
-			lw.WriteHeader(msg.Code)
-			fmt.Fprintln(lw, hErr.Msg)
-			if msg.RequestID != "" {
-				fmt.Fprintln(lw, msg.RequestID)
-			}
-		}
-	case err != nil:
-		const internalServerError = "internal server error"
-		errorMessage := internalServerError
-		if msg.RequestID != "" {
-			errorMessage += "\n" + string(msg.RequestID)
-		}
-		// Handler returned a generic error. Serve an internal server
-		// error, if necessary.
-		msg.Err = err.Error()
-		if lw.code == 0 {
-			msg.Code = http.StatusInternalServerError
-			http.Error(lw, errorMessage, msg.Code)
-		}
+
+	if !h.opts.QuietLoggingIfSuccessful || (msg.Code != http.StatusOK && msg.Code != http.StatusNotModified) {
+		h.opts.Logf("%s", msg)
 	}
 
 	if h.opts.OnCompletion != nil {
 		h.opts.OnCompletion(r, msg)
 	}
 
+	// Closing metrics.
 	if bs := h.opts.BucketedStats; bs != nil && bs.Finished != nil {
 		// Only increment metrics for buckets that result in good HTTP statuses
 		// or when we know the start was already counted.
@@ -487,15 +531,9 @@ func (h retHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 			bs.Finished.Add(bucket, 1)
 		}
 	}
-
-	if !h.opts.QuietLoggingIfSuccessful || (msg.Code != http.StatusOK && msg.Code != http.StatusNotModified) {
-		h.opts.Logf("%s", msg)
-	}
-
 	if h.opts.StatusCodeCounters != nil {
 		h.opts.StatusCodeCounters.Add(responseCodeString(msg.Code/100), 1)
 	}
-
 	if h.opts.StatusCodeCountersFull != nil {
 		h.opts.StatusCodeCountersFull.Add(responseCodeString(msg.Code), 1)
 	}
@@ -579,6 +617,130 @@ func (l loggingResponseWriter) Flush() {
 	f.Flush()
 }
 
+// errorHandler is an http.Handler that wraps a ReturnHandler to render the
+// returned errors to the client and pass them back to any logHandlers.
+type errorHandler struct {
+	rh   ReturnHandler
+	opts ErrorOptions
+}
+
+// ServeHTTP implements the http.Handler interface.
+func (h errorHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
+	logf := h.opts.Logf
+	if l := logger.LogfKey.Value(r.Context()); l != nil {
+		logf = l
+	}
+
+	// Keep track of whether a response gets written.
+	lw, ok := w.(*loggingResponseWriter)
+	if !ok {
+		lw = &loggingResponseWriter{
+			ResponseWriter: w,
+			logf:           logf,
+		}
+	}
+
+	// In case the handler panics, we want to recover and continue logging the
+	// error before raising the panic again for the server to handle.
+	var panicRes any
+	defer func() {
+		if panicRes != nil {
+			panic(panicRes)
+		}
+	}()
+	err := func() (err error) {
+		defer func() {
+			if r := recover(); r != nil {
+				panicRes = r
+				if r == http.ErrAbortHandler {
+					err = http.ErrAbortHandler
+				} else {
+					// Even if r is an error, do not wrap it as an error here as
+					// that would allow things like panic(vizerror.New("foo"))
+					// which is really hard to define the behavior of.
+					var stack [10000]byte
+					n := runtime.Stack(stack[:], false)
+					err = fmt.Errorf("panic: %v\n\n%s", r, stack[:n])
+				}
+			}
+		}()
+		return h.rh.ServeHTTPReturn(lw, r)
+	}()
+	if err == nil {
+		return
+	}
+
+	// Extract a presentable, loggable error.
+	var hOK bool
+	var hErr HTTPError
+	if errors.As(err, &hErr) {
+		hOK = true
+		if hErr.Code == 0 {
+			logf("[unexpected] HTTPError %v did not contain an HTTP status code, sending internal server error", hErr)
+			hErr.Code = http.StatusInternalServerError
+		}
+	} else if v, ok := vizerror.As(err); ok {
+		hErr = Error(http.StatusInternalServerError, v.Error(), nil)
+	} else {
+		// Omit the friendly message so HTTP logs show the bare error that was
+		// returned and we know it's not a HTTPError.
+		hErr = Error(http.StatusInternalServerError, "", err)
+	}
+
+	// Tell the logger what error we wrote back to the client.
+	if pb := errCallback.Value(r.Context()); pb != nil {
+		if hErr.Msg != "" && hErr.Err != nil {
+			pb(hErr.Msg + ": " + hErr.Err.Error())
+		} else if hErr.Err != nil {
+			pb(hErr.Err.Error())
+		} else if hErr.Msg != "" {
+			pb(hErr.Msg)
+		}
+	}
+
+	if lw.code != 0 {
+		if hOK {
+			logf("[unexpected] handler returned HTTPError %v, but already sent a response with code %d", hErr, lw.code)
+		}
+		return
+	}
+
+	// Set a default error message from the status code. Do this after we pass
+	// the error back to the logger so that `return errors.New("oh")` logs as
+	// `"err": "oh"`, not `"err": "internal server error: oh"`.
+	if hErr.Msg == "" {
+		hErr.Msg = http.StatusText(hErr.Code)
+	}
+
+	h.opts.OnError(w, r, hErr)
+}
+
+// writeHTTPError is the default error response formatter.
+func writeHTTPError(w http.ResponseWriter, r *http.Request, hErr HTTPError) {
+	// Default headers set by http.Error.
+	h := w.Header()
+	h.Set("Content-Type", "text/plain; charset=utf-8")
+	h.Set("X-Content-Type-Options", "nosniff")
+
+	// Custom headers from the error.
+	for k, vs := range hErr.Header {
+		h[k] = vs
+	}
+
+	// Write the msg back to the user.
+	w.WriteHeader(hErr.Code)
+	fmt.Fprint(w, hErr.Msg)
+
+	// If it's a plaintext message, add line breaks and RequestID.
+	if strings.HasPrefix(h.Get("Content-Type"), "text/plain") {
+		io.WriteString(w, "\n")
+		if id := RequestIDFromContext(r.Context()); id != "" {
+			io.WriteString(w, id.String())
+			io.WriteString(w, "\n")
+		}
+	}
+}
+
 // HTTPError is an error with embedded HTTP response information.
 //
 // It is the error type to be (optionally) used by Handler.ServeHTTPReturn.

tsweb/tsweb_test.go

@@ -7,6 +7,7 @@
 	"bufio"
 	"context"
 	"errors"
+	"expvar"
 	"fmt"
 	"io"
 	"net"
@@ -19,6 +20,7 @@
 
 	"github.com/google/go-cmp/cmp"
 	"github.com/google/go-cmp/cmp/cmpopts"
+	"tailscale.com/metrics"
 	"tailscale.com/tstest"
 	"tailscale.com/util/must"
 	"tailscale.com/util/vizerror"
@@ -60,11 +62,7 @@ func TestStdHandler(t *testing.T) {
 		}
 
 		req = func(ctx context.Context, url string) *http.Request {
-			ret, err := http.NewRequestWithContext(ctx, "GET", url, nil)
-			if err != nil {
-				panic(err)
-			}
-			return ret
+			return httptest.NewRequest("GET", url, nil).WithContext(ctx)
 		}
 
 		testErr = errors.New("test error")
@@ -278,6 +276,29 @@ func TestStdHandler(t *testing.T) {
 			wantBody: "visible error\n",
 		},
 
+		{
+			name: "handler returns JSON-formatted HTTPError",
+			rh: ReturnHandlerFunc(func(w http.ResponseWriter, r *http.Request) error {
+				h := Error(http.StatusBadRequest, `{"isjson": true}`, errors.New("uh"))
+				h.Header = http.Header{"Content-Type": {"application/json"}}
+				return h
+			}),
+			r:        req(RequestIDKey.WithValue(bgCtx, exampleRequestID), "http://example.com/foo"),
+			wantCode: 400,
+			wantLog: AccessLogRecord{
+				Time:       startTime,
+				Seconds:    1.0,
+				Proto:      "HTTP/1.1",
+				Host:       "example.com",
+				Method:     "GET",
+				RequestURI: "/foo",
+				Err:        `{"isjson": true}: uh`,
+				Code:       400,
+				RequestID:  exampleRequestID,
+			},
+			wantBody: `{"isjson": true}`,
+		},
+
 		{
 			name:     "handler returns user-visible error wrapped by private error with request ID",
 			rh:       handlerErr(0, fmt.Errorf("private internal error: %w", vizerror.New("visible error"))),
@@ -312,7 +333,7 @@ func TestStdHandler(t *testing.T) {
 				Err:        testErr.Error(),
 				Code:       500,
 			},
-			wantBody: "internal server error\n",
+			wantBody: "Internal Server Error\n",
 		},
 
 		{
@@ -331,7 +352,7 @@ func TestStdHandler(t *testing.T) {
 				Code:       500,
 				RequestID:  exampleRequestID,
 			},
-			wantBody: "internal server error\n" + exampleRequestID + "\n",
+			wantBody: "Internal Server Error\n" + exampleRequestID + "\n",
 		},
 
 		{
@@ -440,7 +461,7 @@ func TestStdHandler(t *testing.T) {
 				TLS:        false,
 				Host:       "example.com",
 				Method:     "GET",
-				Code:       404,
+				Code:       200,
 				Err:        "not found",
 				RequestURI: "/",
 			},
@@ -463,66 +484,148 @@ func TestStdHandler(t *testing.T) {
 				TLS:        false,
 				Host:       "example.com",
 				Method:     "GET",
-				Code:       404,
+				Code:       200,
 				Err:        "not found",
 				RequestURI: "/",
 				RequestID:  exampleRequestID,
 			},
 			wantBody: "not found with request ID " + exampleRequestID + "\n",
 		},
+
+		{
+			name: "nested",
+			rh: ReturnHandlerFunc(func(w http.ResponseWriter, r *http.Request) error {
+				// Here we completely handle the web response with an
+				// independent StdHandler that is unaware of the outer
+				// StdHandler and its logger.
+				StdHandler(ReturnHandlerFunc(func(w http.ResponseWriter, r *http.Request) error {
+					return Error(501, "Not Implemented", errors.New("uhoh"))
+				}), HandlerOptions{
+					OnError: func(w http.ResponseWriter, r *http.Request, h HTTPError) {
+						w.Header().Set("Content-Type", "application/json")
+						w.WriteHeader(h.Code)
+						fmt.Fprintf(w, `{"error": %q}`, h.Msg)
+					},
+				}).ServeHTTP(w, r)
+				return nil
+			}),
+			r:        req(RequestIDKey.WithValue(bgCtx, exampleRequestID), "http://example.com/"),
+			wantCode: 501,
+			wantLog: AccessLogRecord{
+				Time:       startTime,
+				Seconds:    1.0,
+				Proto:      "HTTP/1.1",
+				TLS:        false,
+				Host:       "example.com",
+				Method:     "GET",
+				Code:       501,
+				Err:        "Not Implemented: uhoh",
+				RequestURI: "/",
+				RequestID:  exampleRequestID,
+			},
+			wantBody: `{"error": "Not Implemented"}`,
+		},
 	}
 
 	for _, test := range tests {
 		t.Run(test.name, func(t *testing.T) {
-			var logs []AccessLogRecord
+			clock := tstest.NewClock(tstest.ClockOpts{
+				Start: startTime,
+				Step:  time.Second,
+			})
+
+			// Callbacks to track the emitted AccessLogRecords.
+			var (
+				logs   []AccessLogRecord
+				starts []AccessLogRecord
+				comps  []AccessLogRecord
+			)
 			logf := func(fmt string, args ...any) {
 				if fmt == "%s" {
 					logs = append(logs, args[0].(AccessLogRecord))
 				}
 				t.Logf(fmt, args...)
 			}
+			oncomp := func(r *http.Request, msg AccessLogRecord) {
+				comps = append(comps, msg)
+			}
+			onstart := func(r *http.Request, msg AccessLogRecord) {
+				starts = append(starts, msg)
+			}
 
-			clock := tstest.NewClock(tstest.ClockOpts{
-				Start: startTime,
-				Step:  time.Second,
-			})
+			bucket := func(r *http.Request) string { return r.URL.RequestURI() }
 
-			var onStartRecord, onCompletionRecord AccessLogRecord
-			rec := noopHijacker{httptest.NewRecorder(), false}
-			h := StdHandler(test.rh, HandlerOptions{
-				Logf:         logf,
+			// Build the request handler.
+			opts := HandlerOptions{
 				Now: clock.Now,
+
 				OnError:      test.errHandler,
-				OnStart:      func(r *http.Request, alr AccessLogRecord) { onStartRecord = alr },
-				OnCompletion: func(r *http.Request, alr AccessLogRecord) { onCompletionRecord = alr },
-			})
+				Logf:         logf,
+				OnStart:      onstart,
+				OnCompletion: oncomp,
+
+				StatusCodeCounters:     &expvar.Map{},
+				StatusCodeCountersFull: &expvar.Map{},
+				BucketedStats: &BucketedStatsOptions{
+					Bucket:   bucket,
+					Started:  &metrics.LabelMap{},
+					Finished: &metrics.LabelMap{},
+				},
+			}
+			h := StdHandler(test.rh, opts)
+
+			// Pre-create the BucketedStats.{Started,Finished} metric for the
+			// test request's bucket so that even non-200 status codes get
+			// recorded immediately. logHandler tries to avoid counting unknown
+			// paths, so here we're marking them known.
+			opts.BucketedStats.Started.Get(bucket(test.r))
+			opts.BucketedStats.Finished.Get(bucket(test.r))
+
+			// Perform the request.
+			rec := noopHijacker{httptest.NewRecorder(), false}
 			h.ServeHTTP(&rec, test.r)
+
+			// Validate the client received the expected response.
 			res := rec.Result()
 			if res.StatusCode != test.wantCode {
 				t.Errorf("HTTP code = %v, want %v", res.StatusCode, test.wantCode)
 			}
-			if len(logs) != 1 {
-				t.Errorf("handler didn't write a request log")
-				return
-			}
-			errTransform := cmp.Transformer("err", func(e error) string {
-				if e == nil {
-					return ""
-				}
-				return e.Error()
-			})
-			if diff := cmp.Diff(onStartRecord, test.wantLog, errTransform, cmpopts.IgnoreFields(
-				AccessLogRecord{}, "Time", "Seconds", "Code", "Err")); diff != "" {
-				t.Errorf("onStart callback returned unexpected request log (-got+want):\n%s", diff)
-			}
-			if diff := cmp.Diff(onCompletionRecord, test.wantLog, errTransform); diff != "" {
-				t.Errorf("onCompletion callback returned incorrect request log (-got+want):\n%s", diff)
-			}
-			if diff := cmp.Diff(logs[0], test.wantLog, errTransform); diff != "" {
-				t.Errorf("handler wrote incorrect request log (-got+want):\n%s", diff)
-			}
 			if diff := cmp.Diff(rec.Body.String(), test.wantBody); diff != "" {
-				t.Errorf("handler wrote incorrect body (-got+want):\n%s", diff)
+				t.Errorf("handler wrote incorrect body (-got +want):\n%s", diff)
+			}
+
+			// Fields we want to check for in tests but not repeat on every case.
+			test.wantLog.RemoteAddr = "192.0.2.1:1234" // Hard-coded by httptest.NewRequest.
+			test.wantLog.Bytes = len(test.wantBody)
+
+			// Validate the AccessLogRecords written to logf and sent back to
+			// the OnCompletion handler.
+			checkOutput := func(src string, msgs []AccessLogRecord, opts ...cmp.Option) {
+				t.Helper()
+				if len(msgs) != 1 {
+					t.Errorf("%s: expected 1 msg, got: %#v", src, msgs)
+				} else if diff := cmp.Diff(msgs[0], test.wantLog, opts...); diff != "" {
+					t.Errorf("%s: wrong access log (-got +want):\n%s", src, diff)
+				}
+			}
+			checkOutput("hander wrote logs", logs)
+			checkOutput("start msgs", starts, cmpopts.IgnoreFields(AccessLogRecord{}, "Time", "Seconds", "Code", "Err", "Bytes"))
+			checkOutput("completion msgs", comps)
+
+			// Validate the code counters.
+			if got, want := opts.StatusCodeCounters.String(), fmt.Sprintf(`{"%dxx": 1}`, test.wantLog.Code/100); got != want {
+				t.Errorf("StatusCodeCounters: got %s, want %s", got, want)
+			}
+			if got, want := opts.StatusCodeCountersFull.String(), fmt.Sprintf(`{"%d": 1}`, test.wantLog.Code); got != want {
+				t.Errorf("StatusCodeCountersFull: got %s, want %s", got, want)
+			}
+
+			// Validate the bucketed counters.
+			if got, want := opts.BucketedStats.Started.String(), fmt.Sprintf("{%q: 1}", bucket(test.r)); got != want {
+				t.Errorf("BucketedStats.Started: got %q, want %q", got, want)
+			}
+			if got, want := opts.BucketedStats.Finished.String(), fmt.Sprintf("{%q: 1}", bucket(test.r)); got != want {
+				t.Errorf("BucketedStats.Finished: got %s, want %s", got, want)
 			}
 		})
 	}