godev/internal/content: log errors in the content error handler

Generalize the existing error logging for /upload into the content
server. This will help debug failures on the worker.

Change-Id: I4460d458f3ac9c799ea67e38d4ce9e987306095d
Reviewed-on: https://go-review.googlesource.com/c/telemetry/+/600715
Reviewed-by: Hongxiang Jiang <[email protected]>
LUCI-TryBot-Result: Go LUCI <[email protected]>
Auto-Submit: Robert Findley <[email protected]>

Author: findleyr

godev/cmd/telemetrygodev/main.go

@@ -76,7 +76,7 @@ func newHandler(ctx context.Context, cfg *config.Config) http.Handler {
 	mux.Handle("/", handleRoot(render, fsys, buckets.Chart, logger))
 	mux.Handle("/config", handleConfig(fsys, ucfg))
 	// TODO(rfindley): restrict this routing to POST
-	mux.Handle("/upload/", handleUpload(ucfg, buckets.Upload, logger))
+	mux.Handle("/upload/", handleUpload(ucfg, buckets.Upload))
 	mux.Handle("/charts/", handleCharts(render, buckets.Chart))
 	mux.Handle("/data/", handleData(render, buckets.Merge))
 
@@ -267,28 +267,16 @@ func loadCharts(ctx context.Context, date string, bucket storage.BucketHandle) (
 	return charts, nil
 }
 
-func handleUpload(ucfg *tconfig.Config, uploadBucket storage.BucketHandle, log *slog.Logger) content.HandlerFunc {
+func handleUpload(ucfg *tconfig.Config, uploadBucket storage.BucketHandle) content.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) error {
 		if r.Method == "POST" {
 			ctx := r.Context()
-			// Log the error, but only the first 80 characters.
-			// This prevents excessive logging related to broken payloads.
-			// The first line should give us a sense of the failure mode.
-			warn := func(msg string, err error) {
-				errs := []rune(err.Error())
-				if len(errs) > 80 {
-					errs = append(errs[:79], '…')
-				}
-				log.WarnContext(ctx, msg+": "+string(errs))
-			}
 			var report telemetry.Report
 			if err := json.NewDecoder(r.Body).Decode(&report); err != nil {
-				warn("invalid JSON payload", err)
-				return content.Error(err, http.StatusBadRequest)
+				return content.Error(fmt.Errorf("invalid JSON payload: %v", err), http.StatusBadRequest)
 			}
 			if err := validate(&report, ucfg); err != nil {
-				warn("invalid report", err)
-				return content.Error(err, http.StatusBadRequest)
+				return content.Error(fmt.Errorf("invalid report: %v", err), http.StatusBadRequest)
 			}
 			// TODO: capture metrics for collisions.
 			name := fmt.Sprintf("%s/%g.json", report.Week, report.X)

godev/internal/content/content.go

@@ -36,6 +36,7 @@ import (
 	"fmt"
 	"html/template"
 	"io/fs"
+	"log/slog"
 	"net/http"
 	"path"
 	"strconv"
@@ -234,12 +235,20 @@ type contentError struct {
 func (e *contentError) Error() string { return e.err.Error() }
 
 // handleErr writes an error as an HTTP response with a status code.
+//
+// err must be non-nil when calling this function.
 func handleErr(w http.ResponseWriter, req *http.Request, err error, code int) {
-	// TODO(rfindley): should we log here? Do we need to scrub errors before
-	// logging?
 	if cerr, ok := err.(*contentError); ok {
 		code = cerr.Code
 	}
+	// Log the error, but only the first 80 characters.
+	// This prevents excessive logging related to broken payloads.
+	// The first line should give us a sense of the failure mode.
+	errs := []rune(err.Error())
+	if len(errs) > 80 {
+		errs = append(errs[:79], '…')
+	}
+	slog.WarnContext(req.Context(), fmt.Sprintf("request for %q failed with status %d: %s", req.URL.Path, code, string(errs)))
 	if code == http.StatusInternalServerError {
 		http.Error(w, http.StatusText(http.StatusInternalServerError), code)
 	} else {

godev/internal/content/content_test.go

@@ -5,8 +5,10 @@
 package content
 
 import (
+	"bytes"
 	"errors"
 	"io/fs"
+	"log/slog"
 	"net/http"
 	"net/http/httptest"
 	"os"
@@ -21,6 +23,13 @@ import (
 func TestServer_ServeHTTP(t *testing.T) {
 	testenv.NeedsGo1Point(t, 23) // output of some http helpers changed in Go 1.23
 	fsys := os.DirFS("testdata")
+
+	// Reset the default logger after this test.
+	// The default loggers is mutated in the tests below.
+	defer func(l *slog.Logger) {
+		slog.SetDefault(l)
+	}(slog.Default())
+
 	server := Server(fsys,
 		Handler("/data", handleTemplate(fsys)),
 		Handler("/json", handleJSON()),
@@ -30,78 +39,95 @@ func TestServer_ServeHTTP(t *testing.T) {
 	)
 
 	tests := []struct {
-		path     string
-		wantOut  string
-		wantCode int
+		path              string
+		wantOut           string
+		wantCode          int
+		wantLogContaining string // if empty, expect no logs
 	}{
 		{
 			"/index.html",
 			"redirect.html.out",
 			http.StatusMovedPermanently,
+			"",
 		},
 		{
 			"/index",
 			"redirect.out",
 			http.StatusMovedPermanently,
+			"",
 		},
 		{
 			"/json",
 			"json.out",
 			http.StatusOK,
+			"",
 		},
 		{
 			"/text",
 			"text.out",
 			http.StatusOK,
+			"",
 		},
 		{
 			"/error",
 			"error.out",
 			http.StatusBadRequest,
+			"Oh no",
 		},
 		{
 			"/teapot",
 			"teapot.out",
 			http.StatusTeapot,
+			"418",
 		},
 		{
 			"/style.css",
 			"style.css.out",
 			http.StatusOK,
+			"",
 		},
 		{
 			"/",
 			"index.html.out",
 			http.StatusOK,
+			"",
 		},
 		{
 			"/data",
 			"data.html.out",
 			http.StatusOK,
+			"",
 		},
 		{
 			"/markdown",
 			"markdown.md.out",
 			http.StatusOK,
+			"",
 		},
 		{
 			"/404",
 			"404.html.out",
 			http.StatusNotFound,
+			"404",
 		},
 		{
 			"/subdir",
 			"subdir/index.html.out",
 			http.StatusOK,
+			"",
 		},
 		{
 			"/noindex/",
 			"noindex/noindex.html.out",
 			http.StatusOK,
+			"",
 		},
 	}
 	for _, tt := range tests {
 		t.Run(tt.path, func(t *testing.T) {
+			var buf bytes.Buffer
+			slog.SetDefault(slog.New(slog.NewTextHandler(&buf, nil)))
+
 			rr := httptest.NewRecorder()
 			req, err := http.NewRequest("GET", tt.path, nil)
 			if err != nil {
@@ -115,10 +141,13 @@ func TestServer_ServeHTTP(t *testing.T) {
 			}
 			wantBody := strings.TrimSpace(string(data))
 			if diff := cmp.Diff(wantBody, got); diff != "" {
-				t.Errorf("GET %s response body mismatch (-want, +got):\n%s", tt.path, diff)
+				t.Errorf("response body mismatch (-want, +got):\n%s", diff)
 			}
 			if rr.Code != tt.wantCode {
-				t.Errorf("GET %s response code = %d, want %d", tt.path, rr.Code, tt.wantCode)
+				t.Errorf("response code = %d, want %d", rr.Code, tt.wantCode)
+			}
+			if !strings.Contains(buf.String(), tt.wantLogContaining) {
+				t.Errorf("no log containing %q", tt.wantLogContaining)
 			}
 		})
 	}
@@ -169,6 +198,6 @@ func handleTeapot() HandlerFunc {
 
 func handleError() HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) error {
-		return Error(errors.New("Bad Request"), http.StatusBadRequest)
+		return Error(errors.New("Oh no! Bad Request"), http.StatusBadRequest)
 	}
 }

godev/internal/content/testdata/error.out

@@ -1 +1 @@
-Bad Request
+Oh no! Bad Request