smallwebwaf/internal/proxy/request.go

package proxy

import (
	"context"
	"errors"
	"net/http"
	"net/http/httptrace"
	"net/http/httputil"
	"net/netip"
	"net/url"
	"os"
	"slices"
	"strings"
	"sync"
	"sync/atomic"
	"time"

	"sneak.berlin/go/smallwebwaf/internal/ratelimit"
	"sneak.berlin/go/smallwebwaf/internal/requestlog"
)

// flushAfterEachWrite has ReverseProxy pass on each part of the app's
// answer as soon as it arrives.
const flushAfterEachWrite time.Duration = -1

// refusal is smallwebwaf refusing a request, or refusing to go on with it:
// the status the client is answered if the response has not started yet,
// 0 to close the connection without an answer, the action the log line
// names, and the setting whose size or time limit the request passed, if
// that is why.
type refusal struct {
	status int
	action string
	limit  string
}

// request is one request on its way through smallwebwaf, from the moment
// its headers have been read to its log line.
type request struct {
	h  *handler
	in *http.Request
	// rc sets the deadlines of the connection to the client.
	rc   *http.ResponseController
	out  *responseWriter
	body *requestBody // nil for a request without a body
	line requestlog.Line

	client      netip.Addr
	peer        netip.Addr
	peerTrusted bool
	// lookedUp is true once the client's AS number and country have been
	// looked up, whether or not an answer was there.
	lookedUp bool
	start    time.Time
	// checked is when the checks were done, and upstreamStart when the
	// request was handed to the app.
	checked       time.Time
	upstreamStart time.Time
	// cancel ends the request to the app.
	cancel context.CancelFunc
	// refused is the first refusal, from whichever goroutine meets it.
	refused atomic.Pointer[refusal]
	// complete is true once the app's whole answer has been passed on.
	complete bool

	// mu guards what follows. The timeouts run on goroutines of their
	// own, and the transport starts and stops them, and notes the times
	// below, from its own; once timersStopped is set, none of the timeouts
	// acts any more.
	mu                    sync.Mutex
	timersStopped         bool
	clientRequestTimer    *time.Timer
	upstreamRequestTimer  *time.Timer
	upstreamResponseTimer *time.Timer
	// connected is when there was a connection to the app, requestSent
	// when the app had been sent the whole request, and answerStarted
	// when the first byte of its answer arrived.
	connected     time.Time
	requestSent   time.Time
	answerStarted time.Time
}

// newRequest starts handling r: it notes the time, counts the request as
// under way, works out the client, and starts the log line with what is
// known of the request.
func (h *handler) newRequest(w http.ResponseWriter, r *http.Request) *request {
	h.metrics.RequestStarted()

	start := time.Now()
	peer := peerAddress(r)
	trusted := h.config.TrustedProxies
	peerTrusted := isInside(peer, trusted)
	forwardedFor := r.Header.Values("X-Forwarded-For")
	client := clientAddress(peer, forwardedFor, trusted)

	rq := &request{
		h:           h,
		in:          r,
		rc:          http.NewResponseController(w),
		out:         &responseWriter{ResponseWriter: w},
		client:      client,
		peer:        peer,
		peerTrusted: peerTrusted,
		start:       start,
		line: requestlog.Line{
			Time:             requestlog.FormatTime(start),
			Instance:         h.config.InstanceName,
			ClientIP:         client.String(),
			Method:           r.Method,
			Scheme:           scheme(r, peerTrusted),
			Host:             r.Host,
			Path:             r.URL.EscapedPath(),
			Query:            r.URL.RawQuery,
			Protocol:         r.Proto,
			Referer:          r.Referer(),
			UserAgent:        r.UserAgent(),
			RequestID:        requestID(r, peerTrusted),
			PeerIP:           peer.String(),
			ForwardedFor:     strings.Join(forwardedFor, ", "),
			ClientGroup:      clientGroup(client).String(),
			ContentType:      r.Header.Get("Content-Type"),
			RequestHeaders:   requestHeaders(r, h.config.LogRequestHeaders),
			HasAuthorization: len(r.Header.Values("Authorization")) > 0,
			HasCookie:        len(r.Header.Values("Cookie")) > 0,
			Action:           requestlog.ActionForward,
		},
	}

	// A length of -1 is a body whose length was not announced.
	if r.ContentLength > 0 {
		rq.line.ContentLength = r.ContentLength
	}

	if r.Body != http.NoBody {
		rq.body = &requestBody{body: limitBody(r.Body, h.config.RequestMaxBytes), rq: rq}
	}

	return rq
}

// requestHeaders returns the headers of r that names lists, by name in
// lower case, each with its values joined by ", ". Authorization, Cookie
// and Set-Cookie are never among them, whatever names says.
func requestHeaders(r *http.Request, names []string) map[string]string {
	headers := map[string]string{}

	for _, name := range names {
		switch name {
		case "authorization", "cookie", "set-cookie":
			continue
		}

		values := r.Header.Values(name)
		if len(values) > 0 {
			headers[name] = strings.Join(values, ", ")
		}
	}

	return headers
}

// check is the one place where a request can be refused once its client
// is known, before its body is read or anything reaches the app. It
// returns nil to let the request through. The checks of checkClient come
// first, answered with SWWAF_BAN_RESPONSE, or 403 for a block rule, and
// then the size limit, so that a request the rate limits count is counted
// even when it is refused for its size. In observe mode a request
// checkClient refuses goes on to the size limit like any other. ctx is
// the request's own context.
func (rq *request) check(ctx context.Context) *refusal {
	action := rq.checkClient(ctx)

	switch {
	case action == "":
	case rq.h.config.Observe:
		// The log line names what enforce mode would have done.
		rq.line.WouldAction = action
	case action == requestlog.ActionRuleBlocked:
		return &refusal{status: http.StatusForbidden, action: action}
	default:
		return rq.banResponse(action)
	}

	maxBytes := rq.h.config.RequestMaxBytes
	if maxBytes > 0 && rq.in.ContentLength > maxBytes {
		return &refusal{
			status: http.StatusRequestEntityTooLarge,
			action: requestlog.ActionTooLarge,
			limit:  "SWWAF_REQUEST_MAX_BYTES",
		}
	}

	return nil
}

// checkClient runs the checks on the request's client, and returns the
// action of the first that refuses the request, or "" when none does. A
// client in SWWAF_ALLOW_NETS skips them, and is not looked up. For any
// other client, SWWAF_DENY_NETS comes first, then a ban on its netblock,
// so that a client either refuses is not looked up, then the lookup of
// its AS number and country, and then the country lists; a request any of
// them refuses is not counted for the rate limits. Then come the rate
// limits, unless the client is in SWWAF_RATE_LIMIT_EXEMPT_NETS or the
// request's path is exempt under SWWAF_RATE_LIMIT_EXEMPT_PATHS, so that
// every other request is counted, and last the rule files. ctx is the
// request's own context.
func (rq *request) checkClient(ctx context.Context) string {
	cfg := rq.h.config
	if isInside(rq.client, cfg.AllowNets) {
		return ""
	}

	now := rq.h.now()

	if isInside(rq.client, cfg.DenyNets) {
		return requestlog.ActionDenied
	}

	if rq.banned(now) {
		return requestlog.ActionBanned
	}

	rq.lookUp(ctx)

	if rq.countryDenied() {
		return requestlog.ActionCountryDenied
	}

	exempt := isInside(rq.client, cfg.RateLimitExemptNets) ||
		pathExempt(rq.in.URL, cfg.RateLimitExemptPaths)
	if !exempt && rq.limitBroken(now) {
		return requestlog.ActionRateLimited
	}

	return rq.checkRules(now)
}

// pathExempt reports whether the rate limits leave out a request for u
// because of SWWAF_RATE_LIMIT_EXEMPT_PATHS: whether its path as sent, the
// path the app receives, not percent-decoded, starts with one of
// prefixes, so that /%61ssets/x is not under /assets/ for an app whose
// router matches the path as received. A request whose decoded path
// contains .. anywhere or a backslash, or whose path as sent holds an
// encoded slash (%2F or %2f), never is, since an app may act on it as a
// path outside every prefix: /assets/..%2Flogin as /login, or /assets%2Fx
// as one path segment, as Go's router does.
func pathExempt(u *url.URL, prefixes []string) bool {
	decoded := u.Path
	// EscapedPath is the path as the app receives it, not decoded.
	sent := u.EscapedPath()

	if strings.Contains(decoded, "..") || strings.Contains(decoded, `\`) ||
		strings.Contains(strings.ToLower(sent), "%2f") {
		return false
	}

	return slices.ContainsFunc(prefixes, func(prefix string) bool {
		return strings.HasPrefix(sent, prefix)
	})
}

// forward passes the request to the app and the app's answer back. ctx
// is the request's own context.
func (rq *request) forward(ctx context.Context) {
	ctx, cancel := context.WithCancel(ctx)
	defer cancel()

	rq.cancel = cancel
	ctx = httptrace.WithClientTrace(ctx, &httptrace.ClientTrace{
		GotConn:              rq.gotConn,
		WroteRequest:         rq.wroteRequest,
		GotFirstResponseByte: rq.gotFirstResponseByte,
	})

	out := rq.in.WithContext(ctx)
	if rq.body != nil {
		out.Body = rq.body
	}

	reverseProxy := &httputil.ReverseProxy{
		Rewrite:        rq.rewrite,
		Transport:      rq.h.transport,
		FlushInterval:  flushAfterEachWrite,
		ErrorLog:       rq.h.errorLog,
		ModifyResponse: rq.modifyResponse,
		ErrorHandler:   rq.answerError,
	}

	rq.startRequestTimers()
	rq.upstreamStart = time.Now()
	reverseProxy.ServeHTTP(rq.out, out)
}

// rewrite makes the request the app receives: the client's request,
// unchanged, sent to SWWAF_UPSTREAM_URL, with the forwarded headers and
// the request's id set, and, while SWWAF_ADD_LOOKUP_HEADERS is set, the
// client's AS number and country.
func (rq *request) rewrite(pr *httputil.ProxyRequest) {
	upstream := rq.h.config.UpstreamURL
	pr.Out.URL.Scheme = upstream.Scheme
	pr.Out.URL.Host = upstream.Host
	// ReverseProxy drops query parameters it cannot parse; the app gets
	// the query as the client sent it.
	pr.Out.URL.RawQuery = pr.In.URL.RawQuery
	setForwardedHeaders(pr.In, pr.Out, rq.peer, rq.peerTrusted)
	pr.Out.Header.Set(requestIDHeader, rq.line.RequestID)

	if rq.h.config.AddLookupHeaders {
		setLookupHeaders(pr.Out.Header, rq.line.ASN, rq.line.Country)
	}
}

// modifyResponse looks at the app's answer before ReverseProxy passes it
// on.
func (rq *request) modifyResponse(res *http.Response) error {
	rq.line.UpstreamStatus = res.StatusCode

	if res.StatusCode == http.StatusSwitchingProtocols {
		// An upgraded connection, such as a WebSocket, is not cut by the
		// timeouts. ReverseProxy writes this answer straight to the
		// connection it takes over, not through rq.out.
		rq.stopTimers()
		rq.out.status = res.StatusCode
		rq.line.Websocket = true

		return nil
	}

	maxBytes := rq.h.config.ResponseMaxBytes
	if maxBytes > 0 && res.Body != http.NoBody && res.ContentLength > maxBytes {
		rq.refuse(refusal{
			status: http.StatusBadGateway,
			action: requestlog.ActionTooLarge,
			limit:  "SWWAF_RESPONSE_MAX_BYTES",
		})

		return errResponseTooLarge
	}

	res.Body = &responseBody{body: limitBody(res.Body, maxBytes), rq: rq}
	rq.startClientResponseTimeout()

	return nil
}

// answerError is ReverseProxy's ErrorHandler: the request could not be
// passed to the app, or the app's answer cannot be passed on.
func (rq *request) answerError(_ http.ResponseWriter, _ *http.Request, err error) {
	refused := rq.refused.Load()
	if refused == nil {
		if rq.in.Context().Err() != nil {
			return // the client has gone, and there is no one to answer
		}

		rq.h.processLog.Warn("request to the app failed", "error", err.Error())

		refused = &refusal{
			status: http.StatusBadGateway,
			action: requestlog.ActionUpstreamError,
		}
	}

	rq.answer(*refused)
}

// answer sends smallwebwaf's own answer, unless the response has already
// started, and records the refusal for the log line.
func (rq *request) answer(r refusal) {
	rq.refused.CompareAndSwap(nil, &r)

	if rq.out.status != 0 {
		return // too late to answer: the connection can only be cut
	}

	if r.status == 0 {
		// SWWAF_BAN_RESPONSE is close. This panic has Go's server close
		// the connection without an answer, and log nothing; the log line
		// is still written as the handler returns.
		panic(http.ErrAbortHandler)
	}

	// A client found too slow is read no more; any other may go on
	// sending until its time is up, so that Go's server can read the
	// rest of the body and end the request cleanly.
	deadline := rq.clientRequestDeadline()
	if r.status == http.StatusRequestTimeout {
		deadline = time.Now()
	}

	rq.stopReadingBody(deadline)

	timeout := rq.h.config.ClientResponseTimeout
	if timeout > 0 {
		_ = rq.rc.SetWriteDeadline(time.Now().Add(timeout))
	}

	http.Error(rq.out, http.StatusText(r.status), r.status)
}

// refuse records r, unless an earlier refusal was, and ends the request
// to the app, if one was made: smallwebwaf reads the body of a request
// it answers itself too.
func (rq *request) refuse(r refusal) {
	rq.refused.CompareAndSwap(nil, &r)

	if rq.cancel != nil {
		rq.cancel()
	}
}

// finish ends the request's timeouts, counts it in the metrics and writes
// its log line.
func (rq *request) finish() {
	rq.stopTimers()

	refused := rq.refused.Load()
	if refused == nil {
		rq.stopReadingBody(rq.clientRequestDeadline())
	}

	line := &rq.line
	line.Status = rq.out.status
	line.ResponseBytes = rq.out.bytes
	header := rq.out.Header()
	line.ResponseContentType = header.Get("Content-Type")
	line.CacheControl = header.Get("Cache-Control")
	line.Location = header.Get("Location")

	if rq.body != nil {
		line.RequestBytes = rq.body.bytes.Load()
	}

	// limit is the setting whose size or time limit the request passed.
	var limit string

	switch {
	case refused != nil:
		line.Action = refused.action
		limit = refused.limit
	case errors.Is(rq.out.err, os.ErrDeadlineExceeded):
		// The client took longer than SWWAF_CLIENT_RESPONSE_TIMEOUT to
		// take the response.
		line.Action = requestlog.ActionTimedOut
		limit = "SWWAF_CLIENT_RESPONSE_TIMEOUT"
	case !rq.complete && (rq.out.err != nil || rq.in.Context().Err() != nil):
		line.Aborted = true
	}

	now := time.Now()
	duration := now.Sub(rq.start)
	line.DurationTotal = requestlog.Milliseconds(duration)
	line.DurationChecks = timing(rq.start, rq.checked)

	var upstreamDuration time.Duration

	if !rq.upstreamStart.IsZero() {
		upstreamDuration = now.Sub(rq.upstreamStart)
		line.DurationUpstreamTotal = new(requestlog.Milliseconds(upstreamDuration))

		rq.mu.Lock()
		line.DurationUpstreamConnect = timing(rq.upstreamStart, rq.connected)
		line.DurationUpstreamFirstByte = timing(rq.upstreamStart, rq.answerStarted)
		rq.mu.Unlock()
	}

	// Counted before the log line is written, so that the metrics count
	// every request whose line is out.
	rq.h.metrics.RequestEnded(line, limit, duration, upstreamDuration)

	err := requestlog.Write(rq.h.requestLog, line)
	if err != nil {
		rq.h.processLog.Error("writing the request log failed", "error", err.Error())
	}
}

// timing is the time from start to end in milliseconds, for one of the
// log line's timings, or nil when end is zero: what it times never
// happened.
func timing(start, end time.Time) *float64 {
	if end.IsZero() {
		return nil
	}

	return new(requestlog.Milliseconds(end.Sub(start)))
}

// addToHistory adds the request, which has ended, to its client's
// history, and then, for a client that was looked up, the answer kept
// about it to that history and to the notes of the bans on its netblock:
// an answer that came during the request may have come before either was
// there, and one that comes later is added when it comes.
func (rq *request) addToHistory() {
	var requestBytes int64
	if rq.body != nil {
		requestBytes = rq.body.bytes.Load()
	}

	forwarded := !rq.upstreamStart.IsZero()
	group := clientGroup(rq.client)

	rq.h.limiter.AddToHistory(group, rq.h.now(), ratelimit.Request{
		Forwarded:     forwarded,
		Refused:       !forwarded && rq.refused.Load() != nil,
		Status:        rq.out.status,
		RequestBytes:  requestBytes,
		ResponseBytes: rq.out.bytes,
		BrokeLimit:    rq.line.Offence == requestlog.OffenceLimit,
	})

	if !rq.lookedUp {
		return
	}

	answer, kept := rq.h.geojs.Kept(group)
	if kept {
		rq.h.addLookup(answer)
	}
}

// clientRequestDeadline is when the client must have sent its whole
// request, or zero when SWWAF_CLIENT_REQUEST_TIMEOUT is off.
func (rq *request) clientRequestDeadline() time.Time {
	timeout := rq.h.config.ClientRequestTimeout
	if timeout == 0 {
		return time.Time{}
	}

	return rq.start.Add(timeout)
}

// stopReadingBody ends, at deadline, the reading of a client body that has
// not arrived whole: Go's server then reads no more of it, and closes the
// connection after the answer.
func (rq *request) stopReadingBody(deadline time.Time) {
	if rq.body == nil || rq.body.received.Load() {
		return
	}

	_ = rq.rc.SetReadDeadline(deadline)
}

// startRequestTimers starts the timeouts that run while the request goes
// to the app: SWWAF_CLIENT_REQUEST_TIMEOUT until the client has sent its
// whole body, and SWWAF_UPSTREAM_REQUEST_TIMEOUT until the app has been
// sent the whole request.
func (rq *request) startRequestTimers() {
	rq.mu.Lock()
	defer rq.mu.Unlock()

	if rq.body != nil && rq.h.config.ClientRequestTimeout > 0 {
		rq.clientRequestTimer = time.AfterFunc(
			time.Until(rq.clientRequestDeadline()), func() {
				rq.requestTimedOut("SWWAF_CLIENT_REQUEST_TIMEOUT")
			})
	}

	timeout := rq.h.config.UpstreamRequestTimeout
	if timeout > 0 {
		rq.upstreamRequestTimer = time.AfterFunc(timeout, func() {
			rq.requestTimedOut("SWWAF_UPSTREAM_REQUEST_TIMEOUT")
		})
	}
}

// requestTimedOut is called when limit, SWWAF_CLIENT_REQUEST_TIMEOUT or
// SWWAF_UPSTREAM_REQUEST_TIMEOUT, runs out while the request is still on
// its way to the app. The answer names the side smallwebwaf was waiting
// on at that moment: 408 when it was waiting for the client to send more
// of its body, 504 when it was waiting for the app to be reached or to
// take what it had.
func (rq *request) requestTimedOut(limit string) {
	rq.mu.Lock()
	defer rq.mu.Unlock()

	if rq.timersStopped {
		return
	}

	if rq.body == nil || !rq.body.waiting.Load() {
		rq.refuse(refusal{
			status: http.StatusGatewayTimeout,
			action: requestlog.ActionTimedOut,
			limit:  limit,
		})

		return
	}

	rq.refuse(refusal{
		status: http.StatusRequestTimeout,
		action: requestlog.ActionTimedOut,
		limit:  limit,
	})
	// The transport gives up on the app only once its Read of the
	// client's body returns, so that Read is ended now. The lock keeps
	// this from reaching the connection after the request is handled.
	_ = rq.rc.SetReadDeadline(time.Now())
}

// bodyReceived is called once the client has sent its whole body.
func (rq *request) bodyReceived() {
	rq.mu.Lock()
	defer rq.mu.Unlock()

	stopTimer(rq.clientRequestTimer)
}

// gotConn is called once there is a connection to the app, a new one or
// one kept open from an earlier request.
func (rq *request) gotConn(httptrace.GotConnInfo) {
	rq.mu.Lock()
	defer rq.mu.Unlock()

	rq.connected = time.Now()
}

// gotFirstResponseByte is called once the first byte of the app's answer
// has arrived.
func (rq *request) gotFirstResponseByte() {
	rq.mu.Lock()
	defer rq.mu.Unlock()

	rq.answerStarted = time.Now()
}

// wroteRequest is called once the app has been sent the whole request:
// the request timeouts end and SWWAF_UPSTREAM_RESPONSE_TIMEOUT starts.
func (rq *request) wroteRequest(info httptrace.WroteRequestInfo) {
	if info.Err != nil {
		return // the transport gives up, or tries again
	}

	rq.mu.Lock()
	defer rq.mu.Unlock()

	if rq.timersStopped {
		return
	}

	stopTimer(rq.clientRequestTimer)
	stopTimer(rq.upstreamRequestTimer)
	rq.requestSent = time.Now()

	timeout := rq.h.config.UpstreamResponseTimeout
	if timeout > 0 {
		rq.upstreamResponseTimer = time.AfterFunc(timeout, rq.responseTimedOut)
	}
}

// responseTimedOut is called when SWWAF_UPSTREAM_RESPONSE_TIMEOUT runs out
// before the app has sent its whole answer.
func (rq *request) responseTimedOut() {
	rq.mu.Lock()
	defer rq.mu.Unlock()

	if !rq.timersStopped {
		rq.refuse(refusal{
			status: http.StatusGatewayTimeout,
			action: requestlog.ActionTimedOut,
			limit:  "SWWAF_UPSTREAM_RESPONSE_TIMEOUT",
		})
	}
}

// responseReceived is called once the app has sent its whole answer.
func (rq *request) responseReceived() {
	rq.complete = true
	rq.stopTimers()
}

// startClientResponseTimeout sets SWWAF_CLIENT_RESPONSE_TIMEOUT on the
// connection to the client: the response must reach the client within it
// of the end of the request, or of now if the app answers before it has
// the whole request.
func (rq *request) startClientResponseTimeout() {
	timeout := rq.h.config.ClientResponseTimeout
	if timeout == 0 {
		return
	}

	from := rq.sentAt()
	if from.IsZero() {
		from = time.Now()
	}

	_ = rq.rc.SetWriteDeadline(from.Add(timeout))
}

// sentAt is when the app had been sent the whole request, or zero.
func (rq *request) sentAt() time.Time {
	rq.mu.Lock()
	defer rq.mu.Unlock()

	return rq.requestSent
}

// stopTimers stops the request's timeouts and keeps any from starting
// later: the app's answer is complete, the connection upgraded, or the
// request handled.
func (rq *request) stopTimers() {
	rq.mu.Lock()
	defer rq.mu.Unlock()

	rq.timersStopped = true
	stopTimer(rq.clientRequestTimer)
	stopTimer(rq.upstreamRequestTimer)
	stopTimer(rq.upstreamResponseTimer)
}

// stopTimer stops t, which is nil when its timeout is off.
func stopTimer(t *time.Timer) {
	if t != nil {
		t.Stop()
	}
}