Answer 502 for an upstream host with no address or a failed fetch (closes #367)

The image routes answered 500 and logged at error level when the upstream
host had no address, when the fetch failed before the upstream answered,
such as on a refused connection, or when the fetcher refused a redirect.
The fetcher now marks such a failure with ErrUpstreamRequestFailed; a
cancelled fetch is not marked. respondImageError answers it, and
ErrInvalidHost, 502 "upstream error" and logs them at warn level. The TLS
handshake timeout and an address lookup that times out also answered 500;
both are now ErrUpstreamTimeout and answer 504. README Routes lists these
answers.

Model: opus-5-5

README.md

@@ -344,6 +344,8 @@ to any method the list does not give for it.
       connection or a failed TLS handshake.
     - 503 when pixa is busy (see Limits).
     - 503 in maintenance mode.
+    - 504 when the address lookup of the upstream host, or of a host it
+      redirects to, times out.
     - 504 when the upstream has not finished the TLS handshake within 10
       seconds.
     - 504 when the upstream has not sent its response headers within
@@ -410,6 +412,10 @@ instead. Plain HTTP is for development on the browser's own machine. The login
 session cookie is always marked `Secure`. Over plain HTTP a browser keeps such a
 cookie only for its own machine (`localhost`), if at all.
 
+A form refused with 403 gets a page that names the cause and what to do about
+it. pixa logs a `form refused` warning with the request ID and the form-token
+library's reason, such as `origin invalid`.
+
 The image routes answer the errors listed for them with a JSON body holding
 `error`, `status` and `timestamp`.
 

internal/handlers/auth_csrf_internal_test.go

@@ -55,7 +55,7 @@ func newCSRFTestRouter(t *testing.T) (*Handlers, http.Handler) {
 		config:      cfg,
 		sessMgr:     session.NewManager(keys.SessionHashKey, keys.SessionBlockKey),
 		encGen:      encurl.NewGenerator(keys.EncryptedURLKey),
-		csrfProtect: newCSRFProtect(keys.CSRFKey, cfg.Debug),
+		csrfProtect: newCSRFProtect(keys.CSRFKey, cfg.Debug, slog.New(slog.DiscardHandler)),
 	}
 
 	r := chi.NewRouter()

internal/handlers/bodylimit_internal_test.go

@@ -43,7 +43,7 @@ func newBodyLimitTestRouter(
 		config:      cfg,
 		sessMgr:     session.NewManager(keys.SessionHashKey, keys.SessionBlockKey),
 		encGen:      encurl.NewGenerator(keys.EncryptedURLKey),
-		csrfProtect: newCSRFProtect(keys.CSRFKey, cfg.Debug),
+		csrfProtect: newCSRFProtect(keys.CSRFKey, cfg.Debug, slog.New(slog.DiscardHandler)),
 	}
 
 	r := chi.NewRouter()

internal/handlers/csrf.go

@@ -1,18 +1,43 @@
 package handlers
 
 import (
+	"bytes"
+	"errors"
 	"html/template"
+	"log/slog"
 	"net/http"
+	"net/url"
 
+	"github.com/go-chi/chi/v5/middleware"
 	"github.com/gorilla/csrf"
 
 	"sneak.berlin/go/pixa/internal/seal"
+	"sneak.berlin/go/pixa/internal/templates"
+)
+
+// The causes the form-refused page names, each with what to do about it.
+const (
+	causePlainHTTP = "This page was opened over plain HTTP while debug is " +
+		"off. Open it over HTTPS, or turn debug on to use plain HTTP on " +
+		"your own machine."
+	causeHTTPSWithDebug = "This page was opened over HTTPS while debug is " +
+		"on. Turn debug off, or open the page over plain HTTP."
+	causeOtherHost = "The form was sent from another host than the one in " +
+		"the request's Host header. A reverse proxy in front of pixa must " +
+		"pass the Host header on unchanged."
+	causeNoReferer = "The browser sent neither an Origin nor a Referer " +
+		"header, and over HTTPS pixa needs one to check where the form " +
+		"came from. Let the browser send the Referer header to this site."
+	causeStaleToken = "The form token is missing or out of date. Reload " +
+		"the page and submit the form again."
 )
 
 // newCSRFProtect builds the CSRF-protection middleware for the
 // state-mutating HTML form routes. The token lives in its own cookie,
 // independent of the session cookie, so it also protects the login POST
-// where no session exists yet (login CSRF). key signs that cookie.
+// where no session exists yet (login CSRF). key signs that cookie. A
+// refused form is answered by the handler that handleFormRefused returns.
+// log gets a warning with the library's reason, such as "origin invalid".
 //
 // When plaintext is true (local HTTP development), requests are marked
 // plaintext so the library neither demands an https Referer nor sets a
@@ -20,13 +45,14 @@ import (
 // service runs behind a TLS-terminating proxy, so plaintext is false and
 // the library enforces its https Referer origin check.
 func newCSRFProtect(
-	key [seal.KeySize]byte, plaintext bool,
+	key [seal.KeySize]byte, plaintext bool, log *slog.Logger,
 ) func(http.Handler) http.Handler {
 	protect := csrf.Protect(
 		key[:],
 		csrf.Path("/"),
 		csrf.Secure(!plaintext),
 		csrf.SameSite(csrf.SameSiteStrictMode),
+		csrf.ErrorHandler(handleFormRefused(plaintext, log)),
 	)
 
 	if !plaintext {
@@ -42,6 +68,84 @@ func newCSRFProtect(
 	}
 }
 
+// handleFormRefused returns the handler the CSRF middleware calls when it
+// refuses a request. It logs the library's reason with the request ID and
+// answers 403 with a page naming the cause and what to do. A reason that is
+// not a refusal, such as a failure to make a token, answers 500.
+func handleFormRefused(plaintext bool, log *slog.Logger) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		reason := csrf.FailureReason(r)
+		requestID := middleware.GetReqID(r.Context())
+
+		cause := formRefusedCause(r, reason, plaintext)
+		if cause == "" {
+			log.Error("CSRF middleware failed",
+				"request_id", requestID, "error", reason)
+			http.Error(w, "Internal server error",
+				http.StatusInternalServerError)
+
+			return
+		}
+
+		log.Warn("form refused", "request_id", requestID, "reason", reason)
+
+		var page bytes.Buffer
+
+		err := templates.Render(&page, "form_refused.html",
+			struct{ Cause string }{Cause: cause})
+		if err != nil {
+			log.Error("failed to render form refused template", "error", err)
+			http.Error(w, "Internal server error",
+				http.StatusInternalServerError)
+
+			return
+		}
+
+		w.Header().Set("Content-Type", "text/html; charset=utf-8")
+		w.WriteHeader(http.StatusForbidden)
+
+		_, err = page.WriteTo(w)
+		if err != nil {
+			log.Error("failed to write form refused page", "error", err)
+		}
+	})
+}
+
+// formRefusedCause returns the cause the form-refused page names for the
+// CSRF middleware's reason, or "" when the reason is not a refusal.
+func formRefusedCause(r *http.Request, reason error, plaintext bool) string {
+	switch {
+	case errors.Is(reason, csrf.ErrNoToken), errors.Is(reason, csrf.ErrBadToken):
+		return causeStaleToken
+	case errors.Is(reason, csrf.ErrNoReferer):
+		return causeNoReferer
+	case errors.Is(reason, csrf.ErrBadOrigin):
+		return pageAddressCause(r.Header.Get("Origin"), r.Host, plaintext)
+	case errors.Is(reason, csrf.ErrBadReferer):
+		return pageAddressCause(r.Referer(), r.Host, plaintext)
+	default:
+		return ""
+	}
+}
+
+// pageAddressCause returns the cause for a form whose page address, the
+// Origin or Referer header, the CSRF middleware refused. The middleware
+// expects the request's own host, with https when plaintext is false and
+// http when it is true. So on the request's own host, only the scheme was
+// wrong.
+func pageAddressCause(pageAddress, host string, plaintext bool) string {
+	page, err := url.Parse(pageAddress)
+	if err != nil || page.Host != host {
+		return causeOtherHost
+	}
+
+	if plaintext {
+		return causeHTTPSWithDebug
+	}
+
+	return causePlainHTTP
+}
+
 // CSRF returns the CSRF-protection middleware for the login and generator
 // form routes.
 func (s *Handlers) CSRF() func(http.Handler) http.Handler {

internal/handlers/csrf_refused_internal_test.go

@@ -0,0 +1,205 @@
+package handlers
+
+import (
+	"bytes"
+	"context"
+	"encoding/json"
+	"html/template"
+	"log/slog"
+	"net/http"
+	"net/http/httptest"
+	"net/url"
+	"strings"
+	"testing"
+
+	"github.com/go-chi/chi/v5/middleware"
+	"github.com/gorilla/csrf"
+
+	"sneak.berlin/go/pixa/internal/seal"
+)
+
+// refusedFormRequestID is the request ID of the requests postRefusedForm
+// sends, which the warning for a refused form must carry.
+const refusedFormRequestID = "test-request-id"
+
+// TestFormRefusedNamesCause verifies that a form the CSRF middleware refuses
+// answers 403 with a page naming the cause, and logs a warning with the
+// request ID and the middleware's reason.
+func TestFormRefusedNamesCause(t *testing.T) {
+	t.Parallel()
+
+	tests := []struct {
+		name       string
+		debug      bool
+		origin     string
+		referer    string
+		wantCause  string
+		wantReason error
+	}{
+		{
+			name:       "plain HTTP origin with debug off",
+			origin:     "http://example.com",
+			wantCause:  causePlainHTTP,
+			wantReason: csrf.ErrBadOrigin,
+		},
+		{
+			name:       "plain HTTP referer with debug off",
+			referer:    "http://example.com/",
+			wantCause:  causePlainHTTP,
+			wantReason: csrf.ErrBadReferer,
+		},
+		{
+			name:       "origin on another host",
+			origin:     "https://proxy.example.net",
+			wantCause:  causeOtherHost,
+			wantReason: csrf.ErrBadOrigin,
+		},
+		{
+			name:       "referer on another host",
+			referer:    "https://proxy.example.net/",
+			wantCause:  causeOtherHost,
+			wantReason: csrf.ErrBadReferer,
+		},
+		{
+			name:       "HTTPS origin with debug on",
+			debug:      true,
+			origin:     "https://example.com",
+			wantCause:  causeHTTPSWithDebug,
+			wantReason: csrf.ErrBadOrigin,
+		},
+		{
+			name:       "no origin or referer with debug off",
+			wantCause:  causeNoReferer,
+			wantReason: csrf.ErrNoReferer,
+		},
+		{
+			name:       "missing token",
+			debug:      true,
+			origin:     "http://example.com",
+			wantCause:  causeStaleToken,
+			wantReason: csrf.ErrNoToken,
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			t.Parallel()
+
+			rec, logLine := postRefusedForm(t, tt.debug, tt.origin, tt.referer,
+				nil, "")
+			checkFormRefused(t, rec, logLine, tt.wantCause, tt.wantReason)
+		})
+	}
+}
+
+// TestFormRefusedNamesCauseForForeignToken verifies that a form whose token
+// does not match its CSRF cookie answers 403 with a page naming
+// causeStaleToken, and logs a warning with the request ID and the
+// middleware's reason.
+func TestFormRefusedNamesCauseForForeignToken(t *testing.T) {
+	t.Parallel()
+
+	// The router and postRefusedForm derive their CSRF key from
+	// testSigningKey, so cookiesA is valid there and only tokenB is wrong.
+	_, router := newCSRFTestRouter(t)
+	cookiesA, _ := csrfCredentials(t, router, nil)
+	_, tokenB := csrfCredentials(t, router, nil)
+
+	rec, logLine := postRefusedForm(t, true, "http://example.com", "",
+		cookiesA, tokenB)
+	checkFormRefused(t, rec, logLine, causeStaleToken, csrf.ErrBadToken)
+}
+
+// postRefusedForm sends a POST with the given cookies to the CSRF
+// middleware built for debug. It adds the form token and the Origin and
+// Referer headers when they are not empty. It returns the response and the
+// one JSON log line the middleware wrote.
+func postRefusedForm(
+	t *testing.T, debug bool, origin, referer string,
+	cookies []*http.Cookie, token string,
+) (*httptest.ResponseRecorder, map[string]any) {
+	t.Helper()
+
+	keys, err := seal.DeriveKeys(testSigningKey)
+	if err != nil {
+		t.Fatalf("seal.DeriveKeys() error = %v", err)
+	}
+
+	var logs bytes.Buffer
+
+	log := slog.New(slog.NewJSONHandler(&logs, nil))
+	reached := http.HandlerFunc(func(_ http.ResponseWriter, _ *http.Request) {
+		t.Error("the refused form reached the handler behind the middleware")
+	})
+	srv := newCSRFProtect(keys.CSRFKey, debug, log)(reached)
+
+	form := url.Values{loginKeyField: {"x"}}
+	if token != "" {
+		form.Set(csrfTokenField, token)
+	}
+
+	ctx := context.WithValue(context.Background(),
+		middleware.RequestIDKey, refusedFormRequestID)
+	req := httptest.NewRequestWithContext(ctx, http.MethodPost,
+		"http://example.com/", strings.NewReader(form.Encode()))
+	req.Header.Set("Content-Type", "application/x-www-form-urlencoded")
+
+	for _, c := range cookies {
+		req.AddCookie(c)
+	}
+
+	if origin != "" {
+		req.Header.Set("Origin", origin)
+	}
+
+	if referer != "" {
+		req.Header.Set("Referer", referer)
+	}
+
+	rec := httptest.NewRecorder()
+	srv.ServeHTTP(rec, req)
+
+	var logLine map[string]any
+
+	err = json.Unmarshal(logs.Bytes(), &logLine)
+	if err != nil {
+		t.Fatalf("decoding log line %q: %v", logs.String(), err)
+	}
+
+	return rec, logLine
+}
+
+// checkFormRefused checks that rec is a 403 page naming wantCause and that
+// logLine is a warning carrying the request ID and wantReason.
+func checkFormRefused(
+	t *testing.T, rec *httptest.ResponseRecorder, logLine map[string]any,
+	wantCause string, wantReason error,
+) {
+	t.Helper()
+
+	if rec.Code != http.StatusForbidden {
+		t.Errorf("status = %d, want %d", rec.Code, http.StatusForbidden)
+	}
+
+	body := rec.Body.String()
+	t.Logf("body: %s", body)
+
+	if !strings.Contains(body, template.HTMLEscapeString(wantCause)) {
+		t.Errorf("page does not name the cause %q", wantCause)
+	}
+
+	t.Logf("log line: %v", logLine)
+
+	if logLine["level"] != "WARN" || logLine["msg"] != "form refused" {
+		t.Errorf("log line = %v, want a WARN \"form refused\"", logLine)
+	}
+
+	if logLine["request_id"] != refusedFormRequestID {
+		t.Errorf("logged request_id = %v, want %q",
+			logLine["request_id"], refusedFormRequestID)
+	}
+
+	if logLine["reason"] != wantReason.Error() {
+		t.Errorf("logged reason = %v, want %q", logLine["reason"], wantReason)
+	}
+}

internal/handlers/handlers.go

@@ -56,14 +56,16 @@ type Handlers struct {
 
 // New creates a new Handlers instance.
 func New(_ fx.Lifecycle, params Params) *Handlers {
+	log := params.Logger.Get()
+
 	return &Handlers{
-		log:              params.Logger.Get(),
+		log:              log,
 		hc:               params.Healthcheck,
 		config:           params.Config,
 		imgSvc:           params.ImageService,
 		sessMgr:          params.SessionManager,
 		encGen:           params.EncryptedURLGenerator,
-		csrfProtect:      newCSRFProtect(params.Keys.CSRFKey, params.Config.Debug),
+		csrfProtect:      newCSRFProtect(params.Keys.CSRFKey, params.Config.Debug, log),
 		signer:           signature.New(params.Config.SigningKey),
 		allowlist:        allowlist.New(params.Config.AllowlistHosts),
 		refererBlocklist: allowlist.New(params.Config.RefererBlocklist),

internal/httpfetcher/httpfetcher.go

@@ -327,9 +327,11 @@ func upstreamRequestError(err error) error {
 
 	switch {
 	case errors.Is(err, context.DeadlineExceeded),
+		errors.Is(err, ErrUpstreamTimeout),
 		errors.As(err, &netErr) && netErr.Timeout():
 		// A timeout other than the fetch timeout, such as the TLS
-		// handshake timeout, does not match context.DeadlineExceeded
+		// handshake timeout, does not match context.DeadlineExceeded. An
+		// address lookup that timed out is ErrUpstreamTimeout already.
 		return ErrUpstreamTimeout
 	case errors.Is(err, context.Canceled):
 		// The caller cancelled the fetch; the upstream did not fail
@@ -528,7 +530,7 @@ func validateURL(ctx context.Context, fetchURL *neturl.URL, allowHTTP bool) erro
 	// Resolve the host to check IP addresses
 	addrs, err := net.DefaultResolver.LookupIPAddr(ctx, host)
 	if err != nil {
-		return fmt.Errorf("%w: %s", ErrInvalidHost, host)
+		return addressLookupError(host, err)
 	}
 
 	private := slices.ContainsFunc(addrs, func(addr net.IPAddr) bool {
@@ -541,6 +543,17 @@ func validateURL(ctx context.Context, fetchURL *neturl.URL, allowHTTP bool) erro
 	return nil
 }
 
+// addressLookupError returns the error for a failed address lookup of host:
+// ErrUpstreamTimeout when the lookup timed out, ErrInvalidHost otherwise.
+func addressLookupError(host string, err error) error {
+	var netErr net.Error
+	if errors.As(err, &netErr) && netErr.Timeout() {
+		return fmt.Errorf("%w: address lookup of %s", ErrUpstreamTimeout, host)
+	}
+
+	return fmt.Errorf("%w: %s", ErrInvalidHost, host)
+}
+
 // isLocalhost checks if the host is localhost.
 func isLocalhost(host string) bool {
 	host = strings.ToLower(host)
@@ -669,7 +682,7 @@ func dialSSRFSafe(
 	// Resolve the address
 	ips, err := net.DefaultResolver.LookupIP(ctx, "ip", host)
 	if err != nil {
-		return nil, fmt.Errorf("%w: %s", ErrInvalidHost, host)
+		return nil, addressLookupError(host, err)
 	}
 
 	// Check all resolved IPs

internal/httpfetcher/request_failed_internal_test.go

@@ -84,3 +84,65 @@ func TestFetchFailedBeforeAnswer(t *testing.T) {
 		})
 	}
 }
+
+// TestFetchAddressLookupTimedOut checks that a fetch whose address lookup
+// times out fails with ErrUpstreamTimeout, both for the lookup of the source
+// host and for the lookup while connecting. The error must match neither
+// ErrInvalidHost nor ErrUpstreamRequestFailed, which the image routes answer
+// 502. A context whose deadline has passed makes the lookup time out.
+func TestFetchAddressLookupTimedOut(t *testing.T) {
+	t.Parallel()
+
+	checkTimedOut := func(t *testing.T, err error) {
+		t.Helper()
+		t.Logf("Fetch() error: %v", err)
+
+		if !errors.Is(err, ErrUpstreamTimeout) {
+			t.Errorf("Fetch() error = %v, want ErrUpstreamTimeout", err)
+		}
+
+		if errors.Is(err, ErrInvalidHost) || errors.Is(err, ErrUpstreamRequestFailed) {
+			t.Errorf("Fetch() error = %v, must match neither ErrInvalidHost "+
+				"nor ErrUpstreamRequestFailed", err)
+		}
+	}
+
+	t.Run("lookup of the source host", func(t *testing.T) {
+		t.Parallel()
+
+		ctx, cancel := context.WithTimeout(testContext(t), 0)
+		defer cancel()
+
+		f := New(&Config{
+			Timeout:               30 * time.Second,
+			MaxResponseSize:       50 << 20,
+			MaxConnectionsPerHost: 20,
+			MaxConnections:        64,
+		})
+
+		_, err := f.Fetch(ctx, imageSourceOn("cdn.example.com"), "", "")
+		checkTimedOut(t, err)
+	})
+
+	t.Run("lookup while connecting", func(t *testing.T) {
+		t.Parallel()
+
+		// The source host is an address, which validateURL does not look up;
+		// the dialer looks up a name
+		f := New(&Config{
+			Timeout:               30 * time.Second,
+			MaxResponseSize:       50 << 20,
+			MaxConnectionsPerHost: 20,
+			MaxConnections:        64,
+			DialContext: func(ctx context.Context, network, _ string) (net.Conn, error) {
+				ctx, cancel := context.WithTimeout(ctx, 0)
+				defer cancel()
+
+				return dialSSRFSafe(ctx, network, "img.example.com:443", nil)
+			},
+		})
+
+		_, err := f.Fetch(testContext(t), upstreamSource("/image"), "", "")
+		checkTimedOut(t, err)
+	})
+}

internal/templates/form_refused.html

@@ -0,0 +1,22 @@
+<!DOCTYPE html>
+<html lang="en">
+<head>
+    <meta charset="UTF-8">
+    <meta name="viewport" content="width=device-width, initial-scale=1.0">
+    <title>Pixa - Form Refused</title>
+    <link rel="stylesheet" href="/static/style.css">
+</head>
+<body class="login">
+    <div class="card">
+        <h1>Form Refused</h1>
+
+        <div class="error">
+            {{.Cause}}
+        </div>
+
+        <p>
+            <a href="/">Back to the start page</a>
+        </p>
+    </div>
+</body>
+</html>