api: log error responses

Errors returned by API handlers were only shown in the UI banner and left no trace in logs — the VPN gateway failure on Windows was undiagnosable after the banner was dismissed. Handlers write errors with c.JSON(4xx/5xx, ...), which echo treats as successful responses, so no framework hook sees them.

Add an outermost middleware that captures error response bodies (lazily, only once the status is known to be >= 400, capped at 4 KiB) and logs them, plus errors traveling to echo's HTTPErrorHandler: basic auth 401s, route-not-found and recovered panics. 5xx are logged everywhere as errors; 4xx as warnings and only under /api/ to keep SPA static misses and browsers' initial basic-auth 401s out of the logs.

Author: pymq

api/api.go

@@ -104,6 +104,9 @@ func (h *Handler) setupRouter(address string) (*echo.Echo, error) {
 	e.Validator = &customValidator{validator: val}
 
 	// Middleware
+	// First/outermost, so it also sees errors from the middleware below
+	// (basic auth 401s, panics recovered to 500s).
+	e.Use(errorLogMiddleware(h.logger))
 	if !h.conf.DevMode() {
 		e.Use(middleware.Recover())
 	}

api/middleware.go

@@ -0,0 +1,124 @@
+package api
+
+import (
+	"bytes"
+	"errors"
+	"net/http"
+	"strings"
+
+	"github.com/ipfs/go-log/v2"
+	"github.com/labstack/echo/v4"
+)
+
+// errorBodyLogLimit caps how much of an error response body is captured for
+// logging. Error bodies are small JSON objects; the cap only guards against a
+// pathological handler.
+const errorBodyLogLimit = 4 * 1024
+
+// errorLogMiddleware logs every error response, which would otherwise exist
+// only in the UI banner that showed it: handlers write errors directly with
+// c.JSON(4xx/5xx, ...), so from echo's point of view they are successful
+// responses and no framework hook sees them. Must be registered first (as the
+// outermost middleware) — errors from inner middleware (basic auth 401s,
+// panics recovered to 500s) are only visible to middleware outside of them.
+//
+// 5xx are logged everywhere as errors; 4xx as warnings and only under the API
+// prefix — outside it they are browser noise (static file misses, the basic
+// auth 401 every browser session starts with).
+func errorLogMiddleware(logger *log.ZapEventLogger) echo.MiddlewareFunc {
+	return errorLogMiddlewareLogf(func(status int, format string, args ...any) {
+		if status >= http.StatusInternalServerError {
+			logger.Errorf(format, args...)
+		} else {
+			logger.Warnf(format, args...)
+		}
+	})
+}
+
+// errorLogMiddlewareLogf is errorLogMiddleware with the log destination
+// injected, so tests can assert on emitted records.
+func errorLogMiddlewareLogf(logf func(status int, format string, args ...any)) echo.MiddlewareFunc {
+	return func(next echo.HandlerFunc) echo.HandlerFunc {
+		return func(c echo.Context) error {
+			w := &errorCaptureWriter{ResponseWriter: c.Response().Writer}
+			c.Response().Writer = w
+
+			err := next(c)
+			req := c.Request()
+
+			// An error heading to echo's HTTPErrorHandler: it is rendered
+			// after this middleware returns, so the capture below never sees
+			// its body — log the error value itself. If the response is
+			// already committed, the write went through the capture writer
+			// and the branch below reports it instead.
+			if err != nil && !c.Response().Committed {
+				status := http.StatusInternalServerError
+				if httpErr, ok := errors.AsType[*echo.HTTPError](err); ok {
+					status = httpErr.Code
+				}
+				if shouldLogErrorResponse(status, req.URL.Path) {
+					logf(status, "%s %s: %d: %v", req.Method, req.URL.Path, status, err)
+				}
+				return err
+			}
+
+			if w.status >= 400 && shouldLogErrorResponse(w.status, req.URL.Path) {
+				body := bytes.TrimSpace(w.body.Bytes())
+				truncated := ""
+				if w.truncated {
+					truncated = " (body truncated)"
+				}
+				logf(w.status, "%s %s: %d: %s%s", req.Method, req.URL.Path, w.status, body, truncated)
+			}
+			return err
+		}
+	}
+}
+
+func shouldLogErrorResponse(status int, path string) bool {
+	return status >= http.StatusInternalServerError || strings.HasPrefix(path, V0Prefix)
+}
+
+// errorCaptureWriter passes everything through to the underlying
+// ResponseWriter and additionally keeps a copy of the body — but only once
+// the status is known to be an error, so success responses (log dumps,
+// metrics scrapes, pprof profiles) are never buffered.
+type errorCaptureWriter struct {
+	http.ResponseWriter
+	status    int
+	body      bytes.Buffer
+	truncated bool
+}
+
+func (w *errorCaptureWriter) WriteHeader(status int) {
+	w.status = status
+	w.ResponseWriter.WriteHeader(status)
+}
+
+func (w *errorCaptureWriter) Write(b []byte) (int, error) {
+	if w.status >= 400 {
+		free := errorBodyLogLimit - w.body.Len()
+		if len(b) <= free {
+			w.body.Write(b)
+		} else {
+			w.body.Write(b[:free])
+			w.truncated = true
+		}
+	}
+	return w.ResponseWriter.Write(b)
+}
+
+// Flush keeps streaming endpoints (pprof profiles) working: echo's
+// Response.Flush type-asserts the underlying writer to http.Flusher and would
+// panic on a wrapper without it.
+func (w *errorCaptureWriter) Flush() {
+	if f, ok := w.ResponseWriter.(http.Flusher); ok {
+		f.Flush()
+	}
+}
+
+// Unwrap lets http.ResponseController reach the underlying writer's optional
+// interfaces.
+func (w *errorCaptureWriter) Unwrap() http.ResponseWriter {
+	return w.ResponseWriter
+}

api/middleware_test.go

@@ -0,0 +1,166 @@
+package api
+
+import (
+	"fmt"
+	"net/http"
+	"net/http/httptest"
+	"strings"
+	"testing"
+
+	"github.com/labstack/echo/v4"
+	"github.com/stretchr/testify/require"
+)
+
+// logRecord is one captured logf call.
+type logRecord struct {
+	status  int
+	message string
+}
+
+func newMiddlewareTestEcho() (*echo.Echo, *[]logRecord) {
+	records := &[]logRecord{}
+	e := echo.New()
+	e.Use(errorLogMiddlewareLogf(func(status int, format string, args ...any) {
+		*records = append(*records, logRecord{status: status, message: fmt.Sprintf(format, args...)})
+	}))
+	return e, records
+}
+
+func doRequest(e *echo.Echo, method, path string) *httptest.ResponseRecorder {
+	req := httptest.NewRequest(method, path, nil)
+	rec := httptest.NewRecorder()
+	e.ServeHTTP(rec, req)
+	return rec
+}
+
+func TestErrorLogMiddleware(t *testing.T) {
+	apiPath := V0Prefix + "test"
+
+	t.Run("success response is passed through and not logged", func(t *testing.T) {
+		e, records := newMiddlewareTestEcho()
+		bigBody := strings.Repeat("x", 3*errorBodyLogLimit)
+		e.GET(apiPath, func(c echo.Context) error {
+			return c.String(http.StatusOK, bigBody)
+		})
+
+		rec := doRequest(e, http.MethodGet, apiPath)
+		require.Equal(t, http.StatusOK, rec.Code)
+		require.Equal(t, bigBody, rec.Body.String())
+		require.Empty(t, *records)
+	})
+
+	t.Run("handler-written 4xx on API path is logged with body", func(t *testing.T) {
+		e, records := newMiddlewareTestEcho()
+		e.POST(apiPath, func(c echo.Context) error {
+			return c.JSON(http.StatusBadRequest, ErrorMessage("invalid peer id"))
+		})
+
+		rec := doRequest(e, http.MethodPost, apiPath)
+		require.Equal(t, http.StatusBadRequest, rec.Code)
+		require.Len(t, *records, 1)
+		require.Equal(t, http.StatusBadRequest, (*records)[0].status)
+		require.Contains(t, (*records)[0].message, "POST "+apiPath+": 400:")
+		require.Contains(t, (*records)[0].message, "invalid peer id")
+	})
+
+	t.Run("4xx outside API prefix is not logged", func(t *testing.T) {
+		e, records := newMiddlewareTestEcho()
+		e.GET("/static.js", func(c echo.Context) error {
+			return c.String(http.StatusNotFound, "404 page not found")
+		})
+
+		rec := doRequest(e, http.MethodGet, "/static.js")
+		require.Equal(t, http.StatusNotFound, rec.Code)
+		require.Empty(t, *records)
+	})
+
+	t.Run("5xx outside API prefix is still logged", func(t *testing.T) {
+		e, records := newMiddlewareTestEcho()
+		e.GET("/broken", func(c echo.Context) error {
+			return c.JSON(http.StatusInternalServerError, ErrorMessage("boom"))
+		})
+
+		doRequest(e, http.MethodGet, "/broken")
+		require.Len(t, *records, 1)
+		require.Equal(t, http.StatusInternalServerError, (*records)[0].status)
+	})
+
+	t.Run("echo HTTPError is logged with its status and rendered by echo", func(t *testing.T) {
+		e, records := newMiddlewareTestEcho()
+		e.GET(apiPath, func(c echo.Context) error {
+			return echo.NewHTTPError(http.StatusUnauthorized, "bad credentials")
+		})
+
+		rec := doRequest(e, http.MethodGet, apiPath)
+		require.Equal(t, http.StatusUnauthorized, rec.Code)
+		require.Contains(t, rec.Body.String(), "bad credentials")
+		require.Len(t, *records, 1)
+		require.Equal(t, http.StatusUnauthorized, (*records)[0].status)
+		require.Contains(t, (*records)[0].message, "bad credentials")
+	})
+
+	t.Run("plain error from handler is logged as 500", func(t *testing.T) {
+		e, records := newMiddlewareTestEcho()
+		e.GET(apiPath, func(c echo.Context) error {
+			return fmt.Errorf("database exploded")
+		})
+
+		rec := doRequest(e, http.MethodGet, apiPath)
+		require.Equal(t, http.StatusInternalServerError, rec.Code)
+		require.Len(t, *records, 1)
+		require.Equal(t, http.StatusInternalServerError, (*records)[0].status)
+		require.Contains(t, (*records)[0].message, "database exploded")
+	})
+
+	t.Run("route not found under API prefix is logged", func(t *testing.T) {
+		e, records := newMiddlewareTestEcho()
+
+		rec := doRequest(e, http.MethodGet, V0Prefix+"no/such/route")
+		require.Equal(t, http.StatusNotFound, rec.Code)
+		require.Len(t, *records, 1)
+		require.Equal(t, http.StatusNotFound, (*records)[0].status)
+	})
+
+	t.Run("oversized error body is truncated in the log, intact on the wire", func(t *testing.T) {
+		e, records := newMiddlewareTestEcho()
+		bigError := strings.Repeat("e", 2*errorBodyLogLimit)
+		e.GET(apiPath, func(c echo.Context) error {
+			return c.String(http.StatusBadRequest, bigError)
+		})
+
+		rec := doRequest(e, http.MethodGet, apiPath)
+		require.Equal(t, bigError, rec.Body.String())
+		require.Len(t, *records, 1)
+		message := (*records)[0].message
+		require.Contains(t, message, "(body truncated)")
+		// message = "GET <path>: 400: <capped body> (body truncated)" — the
+		// captured part must be capped at errorBodyLogLimit, not the full 2x.
+		require.Less(t, len(message), errorBodyLogLimit+200)
+	})
+
+	t.Run("committed response with error returned is logged once", func(t *testing.T) {
+		e, records := newMiddlewareTestEcho()
+		e.GET(apiPath, func(c echo.Context) error {
+			_ = c.JSON(http.StatusBadRequest, ErrorMessage("written and returned"))
+			return fmt.Errorf("handler also returned an error")
+		})
+
+		rec := doRequest(e, http.MethodGet, apiPath)
+		require.Equal(t, http.StatusBadRequest, rec.Code)
+		require.Len(t, *records, 1)
+		require.Contains(t, (*records)[0].message, "written and returned")
+	})
+
+	t.Run("Flush is passed through to the underlying writer", func(t *testing.T) {
+		e, _ := newMiddlewareTestEcho()
+		e.GET(apiPath, func(c echo.Context) error {
+			_ = c.String(http.StatusOK, "chunk")
+			c.Response().Flush()
+			return nil
+		})
+
+		rec := doRequest(e, http.MethodGet, apiPath)
+		require.Equal(t, http.StatusOK, rec.Code)
+		require.True(t, rec.Flushed)
+	})
+}