reverseproxy: Add _ms placeholders for proxy durations (#4666)

* reverseproxy: Add `_ms` placeholders for proxy durations

* Add http.request.duration_ms

Also add comments, and change duration_sec to duration_ms

* Add response.duration_ms for consistency

* Add missing godoc comment

Co-authored-by: Matthew Holt <mholt@users.noreply.github.com>

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.duration_ms}` | Same as 'duration', but in milliseconds.
 // `{http.request.uuid}` | The request unique identifier
 // `{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

modules/caddyhttp/replacer.go

@@ -148,6 +148,9 @@ func addHTTPVarsToReplacer(repl *caddy.Replacer, req *http.Request, w http.Respo
 			case "http.request.duration":
 				start := GetVar(req.Context(), "start_time").(time.Time)
 				return time.Since(start), true
+			case "http.request.duration_ms":
+				start := GetVar(req.Context(), "start_time").(time.Time)
+				return time.Since(start).Seconds() * 1e3, true // multiply seconds to preserve decimal (see #4666)
 			case "http.request.uuid":
 				id := GetVar(req.Context(), "uuid").(*requestID)
 				return id.String(), true

modules/caddyhttp/reverseproxy/reverseproxy.go

@@ -58,8 +58,11 @@ func init() {
 // `{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.latency_ms}` | Same as 'latency', but in milliseconds.
 // `{http.reverse_proxy.upstream.duration}` | Time spent proxying to the upstream, including writing response body to client.
+// `{http.reverse_proxy.upstream.duration_ms}` | Same as 'upstream.duration', but in milliseconds.
 // `{http.reverse_proxy.duration}` | Total time spent proxying, including selecting an upstream, retries, and writing response.
+// `{http.reverse_proxy.duration_ms}` | Same as 'duration', but in milliseconds.
 type Handler struct {
 	// Configures the method of transport for the proxy. A transport
 	// is what performs the actual "round trip" to the backend.
@@ -400,6 +403,7 @@ func (h *Handler) ServeHTTP(w http.ResponseWriter, r *http.Request, next caddyht
 	defer func() {
 		// total proxying duration, including time spent on LB and retries
 		repl.Set("http.reverse_proxy.duration", time.Since(start))
+		repl.Set("http.reverse_proxy.duration_ms", time.Since(start).Seconds()*1e3) // multiply seconds to preserve decimal (see #4666)
 	}()
 
 	// in the proxy loop, each iteration is an attempt to proxy the request,
@@ -724,6 +728,7 @@ func (h *Handler) reverseProxy(rw http.ResponseWriter, req *http.Request, repl *
 
 	// duration until upstream wrote response headers (roundtrip duration)
 	repl.Set("http.reverse_proxy.upstream.latency", duration)
+	repl.Set("http.reverse_proxy.upstream.latency_ms", duration.Seconds()*1e3) // multiply seconds to preserve decimal (see #4666)
 
 	// update circuit breaker on current conditions
 	if di.Upstream.cb != nil {
@@ -909,6 +914,7 @@ func (h Handler) finalizeResponse(
 
 	// total duration spent proxying, including writing response body
 	repl.Set("http.reverse_proxy.upstream.duration", time.Since(start))
+	repl.Set("http.reverse_proxy.upstream.duration_ms", time.Since(start).Seconds()*1e3)
 
 	if len(res.Trailer) == announcedTrailers {
 		copyHeader(rw.Header(), res.Trailer)

modules/caddyhttp/server.go

@@ -190,6 +190,7 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 			repl.Set("http.response.status", wrec.Status())
 			repl.Set("http.response.size", wrec.Size())
 			repl.Set("http.response.duration", duration)
+			repl.Set("http.response.duration_ms", duration.Seconds()*1e3) // multiply seconds to preserve decimal (see #4666)
 
 			logger := accLog
 			if s.Logs != nil {