From 6722ae3a835702073682e020d8736140fc04538e Mon Sep 17 00:00:00 2001 From: Matt Holt Date: Mon, 22 Feb 2021 11:57:21 -0700 Subject: 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 --- modules/caddyhttp/app.go | 1 + modules/caddyhttp/replacer.go | 6 ++++++ modules/caddyhttp/reverseproxy/reverseproxy.go | 22 ++++++++++++++++------ 3 files changed, 23 insertions(+), 6 deletions(-) (limited to 'modules') diff --git a/modules/caddyhttp/app.go b/modules/caddyhttp/app.go index 4f5bc84..8285200 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 5a0efce..d0767f0 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 76506ca..d2d01e6 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 -- cgit v1.2.3