Log the rest of the request log's fields (closes #79)

Each request log line now has the fields "Request log" in SPEC.md lists
whose features are built: instance (SWWAF_INSTANCE_NAME), scheme,
request_id (a trusted proxy's X-Request-ID or a new one, sent on to the
app), forwarded_for, client_group, content_type, content_length, the
headers SWWAF_LOG_REQUEST_HEADERS names, has_authorization, has_cookie,
websocket, response_content_type, cache_control, location, counts and
the timings. Authorization, Cookie and Set-Cookie values are never
logged. An entry of SWWAF_LOG_REQUEST_HEADERS that is not a header name,
or is Host or Transfer-Encoding, stops the start.

Deviation: counts has request totals only.
Deviation: SWWAF_INSTANCE_NAME is on request lines only.

Model: opus-5-5

internal/proxy/request.go

@@ -8,6 +8,7 @@ import (
 	"net/http/httputil"
 	"net/netip"
 	"os"
+	"strings"
 	"sync"
 	"sync/atomic"
 	"time"
@@ -46,7 +47,9 @@ type request struct {
 	peer        netip.Addr
 	peerTrusted bool
 	start       time.Time
-	// upstreamStart is when the request was handed to the app.
+	// 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
@@ -56,26 +59,34 @@ type request struct {
 	complete bool
 
 	// mu guards what follows. The timeouts run on goroutines of their
-	// own, and the transport starts and stops them from its own; once
-	// timersStopped is set, none of them acts any more.
+	// 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
-	// requestSent is when the app had been sent the whole request.
-	requestSent time.Time
+	// 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, and works out the client.
+// 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
-	client := clientAddress(peer, r.Header.Values("X-Forwarded-For"), trusted)
+	peerTrusted := isInside(peer, trusted)
+	forwardedFor := r.Header.Values("X-Forwarded-For")
+	client := clientAddress(peer, forwardedFor, trusted)
 
 	rq := &request{
 		h:           h,
@@ -84,22 +95,37 @@ func (h *handler) newRequest(w http.ResponseWriter, r *http.Request) *request {
 		out:         &responseWriter{ResponseWriter: w},
 		client:      client,
 		peer:        peer,
-		peerTrusted: isInside(peer, trusted),
+		peerTrusted: peerTrusted,
 		start:       start,
 		line: requestlog.Line{
-			Time:      requestlog.FormatTime(start),
-			ClientIP:  client.String(),
-			PeerIP:    peer.String(),
-			Method:    r.Method,
-			Host:      r.Host,
-			Path:      r.URL.EscapedPath(),
-			Query:     r.URL.RawQuery,
-			Protocol:  r.Proto,
-			Referer:   r.Referer(),
-			UserAgent: r.UserAgent(),
-			Action:    requestlog.ActionForward,
+			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}
 	}
@@ -107,6 +133,27 @@ func (h *handler) newRequest(w http.ResponseWriter, r *http.Request) *request {
 	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
@@ -182,7 +229,9 @@ func (rq *request) forward(ctx context.Context) {
 
 	rq.cancel = cancel
 	ctx = httptrace.WithClientTrace(ctx, &httptrace.ClientTrace{
-		WroteRequest: rq.wroteRequest,
+		GotConn:              rq.gotConn,
+		WroteRequest:         rq.wroteRequest,
+		GotFirstResponseByte: rq.gotFirstResponseByte,
 	})
 
 	out := rq.in.WithContext(ctx)
@@ -205,7 +254,8 @@ func (rq *request) forward(ctx context.Context) {
 }
 
 // rewrite makes the request the app receives: the client's request,
-// unchanged, sent to SWWAF_UPSTREAM_URL, with the forwarded headers set.
+// unchanged, sent to SWWAF_UPSTREAM_URL, with the forwarded headers and
+// the request's id set.
 func (rq *request) rewrite(pr *httputil.ProxyRequest) {
 	upstream := rq.h.config.UpstreamURL
 	pr.Out.URL.Scheme = upstream.Scheme
@@ -214,6 +264,7 @@ func (rq *request) rewrite(pr *httputil.ProxyRequest) {
 	// 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)
 }
 
 // modifyResponse looks at the app's answer before ReverseProxy passes it
@@ -227,6 +278,7 @@ func (rq *request) modifyResponse(res *http.Response) error {
 		// connection it takes over, not through rq.out.
 		rq.stopTimers()
 		rq.out.status = res.StatusCode
+		rq.line.Websocket = true
 
 		return nil
 	}
@@ -322,6 +374,10 @@ func (rq *request) finish() {
 	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()
@@ -346,12 +402,18 @@ func (rq *request) finish() {
 	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 = requestlog.Milliseconds(upstreamDuration)
+		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
@@ -364,6 +426,17 @@ func (rq *request) finish() {
 	}
 }
 
+// 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.
 func (rq *request) addToHistory() {
@@ -473,6 +546,24 @@ func (rq *request) bodyReceived() {
 	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) {