reverseproxy: Add duration/latency placeholders (close #4012) (#4013)

* reverseproxy: Add duration/latency placeholders (close #4012) (and #2268)

Adds 4 placeholders, one is actually outside reverse proxy though:

{http.request.duration} is how long since the server decoded the HTTP request (headers).
{http.reverse_proxy.upstream.latency} is how long it took a proxy upstream to write the response header.
{http.reverse_proxy.upstream.duration} is total time proxying to the upstream, including writing response body to client.
{http.reverse_proxy.duration} is total time spent proxying, including selecting an upstream and retries.

Obviously, most of these are only useful at the end of a request, like when writing response headers or logs.

See also: https://caddy.community/t/any-equivalent-of-request-time-and-upstream-header-time-from-nginx/11418

* Add new placeholders to documentation

3 files changed, 23 insertions, 6 deletions

diff --git a/modules/caddyhttp/app.go b/modules/caddyhttp/app.go
index 4f5bc845e..8285200fb 100644
--- a/modules/caddyhttp/app.go
+++ b/modules/caddyhttp/app.go
@@ -49,6 +49,7 @@ func init() {
 // ------------|---------------
 // `{http.request.body}` | The request body (⚠️ inefficient; use only for debugging)
 // `{http.request.cookie.*}` | HTTP request cookie
+// `{http.request.duration}` | Time up to now spent handling the request (after decoding headers from client)
 // `{http.request.header.*}` | Specific request header field
 // `{http.request.host.labels.*}` | Request host labels (0-based from right); e.g. for foo.example.com: 0=com, 1=example, 2=foo
 // `{http.request.host}` | The host part of the request's Host header
diff --git a/modules/caddyhttp/replacer.go b/modules/caddyhttp/replacer.go
index 5a0efce46..d0767f097 100644
--- a/modules/caddyhttp/replacer.go
+++ b/modules/caddyhttp/replacer.go
@@ -36,6 +36,7 @@ import (
 	"path"
 	"strconv"
 	"strings"
+	"time"
 
 	"github.com/caddyserver/caddy/v2"
 	"github.com/caddyserver/caddy/v2/modules/caddytls"
@@ -52,6 +53,8 @@ func NewTestReplacer(req *http.Request) *caddy.Replacer {
 }
 
 func addHTTPVarsToReplacer(repl *caddy.Replacer, req *http.Request, w http.ResponseWriter) {
+	SetVar(req.Context(), "start_time", time.Now())
+
 	httpVars := func(key string) (interface{}, bool) {
 		if req != nil {
 			// query string parameters
@@ -140,6 +143,9 @@ func addHTTPVarsToReplacer(repl *caddy.Replacer, req *http.Request, w http.Respo
 				return dir, true
 			case "http.request.uri.query":
 				return req.URL.RawQuery, true
+			case "http.request.duration":
+				start := GetVar(req.Context(), "start_time").(time.Time)
+				return time.Since(start), true
 			case "http.request.body":
 				if req.Body == nil {
 					return "", true
diff --git a/modules/caddyhttp/reverseproxy/reverseproxy.go b/modules/caddyhttp/reverseproxy/reverseproxy.go
index 76506ca85..d2d01e6c9 100644
--- a/modules/caddyhttp/reverseproxy/reverseproxy.go
+++ b/modules/caddyhttp/reverseproxy/reverseproxy.go
@@ -43,7 +43,7 @@ func init() {
 // Handler implements a highly configurable and production-ready reverse proxy.
 //
 // Upon proxying, this module sets the following placeholders (which can be used
-// both within and after this handler):
+// both within and after this handler; for example, in response headers):
 //
 // Placeholder | Description
 // ------------|-------------
@@ -54,6 +54,9 @@ func init() {
 // `{http.reverse_proxy.upstream.requests}` | The approximate current number of requests to the upstream
 // `{http.reverse_proxy.upstream.max_requests}` | The maximum approximate number of requests allowed to the upstream
 // `{http.reverse_proxy.upstream.fails}` | The number of recent failed requests to the upstream
+// `{http.reverse_proxy.upstream.latency}` | How long it took the proxy upstream to write the response header.
+// `{http.reverse_proxy.upstream.duration}` | Time spent proxying to the upstream, including writing response body to client.
+// `{http.reverse_proxy.duration}` | Total time spent proxying, including selecting an upstream, retries, and writing response.
 type Handler struct {
 	// Configures the method of transport for the proxy. A transport
 	// is what performs the actual "round trip" to the backend.
@@ -370,6 +373,10 @@ func (h *Handler) ServeHTTP(w http.ResponseWriter, r *http.Request, next caddyht
 	}()
 
 	start := time.Now()
+	defer func() {
+		// total proxying duration, including time spent on LB and retries
+		repl.Set("http.reverse_proxy.duration", time.Since(start))
+	}()
 
 	var proxyErr error
 	for {
@@ -419,7 +426,7 @@ func (h *Handler) ServeHTTP(w http.ResponseWriter, r *http.Request, next caddyht
 		}
 
 		// proxy the request to that upstream
-		proxyErr = h.reverseProxy(w, r, dialInfo, next)
+		proxyErr = h.reverseProxy(w, r, repl, dialInfo, next)
 		if proxyErr == nil || proxyErr == context.Canceled {
 			// context.Canceled happens when the downstream client
 			// cancels the request, which is not our failure
@@ -522,7 +529,7 @@ func (h Handler) prepareRequest(req *http.Request) error {
 // reverseProxy performs a round-trip to the given backend and processes the response with the client.
 // (This method is mostly the beginning of what was borrowed from the net/http/httputil package in the
 // Go standard library which was used as the foundation.)
-func (h *Handler) reverseProxy(rw http.ResponseWriter, req *http.Request, di DialInfo, next caddyhttp.Handler) error {
+func (h *Handler) reverseProxy(rw http.ResponseWriter, req *http.Request, repl *caddy.Replacer, di DialInfo, next caddyhttp.Handler) error {
 	_ = di.Upstream.Host.CountRequest(1)
 	//nolint:errcheck
 	defer di.Upstream.Host.CountRequest(-1)
@@ -547,6 +554,9 @@ func (h *Handler) reverseProxy(rw http.ResponseWriter, req *http.Request, di Dia
 		zap.Object("headers", caddyhttp.LoggableHTTPHeader(res.Header)),
 		zap.Int("status", res.StatusCode))
 
+	// duration until upstream wrote response headers (roundtrip duration)
+	repl.Set("http.reverse_proxy.upstream.latency", duration)
+
 	// update circuit breaker on current conditions
 	if di.Upstream.cb != nil {
 		di.Upstream.cb.RecordMetric(res.StatusCode, duration)
@@ -579,8 +589,6 @@ func (h *Handler) reverseProxy(rw http.ResponseWriter, req *http.Request, di Dia
 			continue
 		}
 
-		repl := req.Context().Value(caddy.ReplacerCtxKey).(*caddy.Replacer)
-
 		// if configured to only change the status code, do that then continue regular proxy response
 		if statusCodeStr := rh.StatusCode.String(); statusCodeStr != "" {
 			statusCode, err := strconv.Atoi(repl.ReplaceAll(statusCodeStr, ""))
@@ -625,7 +633,6 @@ func (h *Handler) reverseProxy(rw http.ResponseWriter, req *http.Request, di Dia
 	if h.Headers != nil && h.Headers.Response != nil {
 		if h.Headers.Response.Require == nil ||
 			h.Headers.Response.Require.Match(res.StatusCode, res.Header) {
-			repl := req.Context().Value(caddy.ReplacerCtxKey).(*caddy.Replacer)
 			h.Headers.Response.ApplyTo(res.Header, repl)
 		}
 	}
@@ -673,6 +680,9 @@ func (h *Handler) reverseProxy(rw http.ResponseWriter, req *http.Request, di Dia
 		}
 	}
 
+	// total duration spent proxying, including writing response body
+	repl.Set("http.reverse_proxy.upstream.duration", duration)
+
 	if len(res.Trailer) == announcedTrailers {
 		copyHeader(rw.Header(), res.Trailer)
 		return nil