Server-Timing HTTP header field (#657)

* Implement Server-Timing HTTP header field parser

* Implement Server-Timing header

* Fix panic in test envs

* Send our header first

* Fix test

* Fix test (unordered list)

* Setting for Server-Timing

* Improve docu

* Fix test

* Update docu

* Integration test

* Update comment

* Use const instead of string

* Add 'total' time to the timings

* Simplify code

* Update config/settings.go

Co-authored-by: Johannes Koch <53434855+johakoch@users.noreply.github.com>

* Add link in comment

* Update setting name and docs

* Change numeration of vars

* headers => header (singular)

* Suffix all metrics if at least one collides with other headers

* Changelog

Co-authored-by: Johannes Koch <53434855+johakoch@users.noreply.github.com>

CHANGELOG.md

@@ -6,6 +6,7 @@ Unreleased changes are available as `avenga/couper:edge` container.
 
 * **Added**
   * [`beta_job`](https://docs.couper.io/configuration/block/job) block to describe one or more job `definitions` for simple recurring http tasks ([#610](https://github.com/avenga/couper/pull/610))
+  * [`server_timing_header`](https://docs.couper.io/configuration/block/settings) setting, that allows Couper to include an additional `Server-Timing` HTTP response header field detailing connection and transport relevant metrics for each backend request. ([#657](https://github.com/avenga/couper/pull/657))
 
 * **Changed**
   * Use nested `jwt_signing_profile` block in [`oauth2` block](https://docs.couper.io/configuration/block/oauth2) for `grant_type` `"urn:ietf:params:oauth:grant-type:jwt-bearer"` in absence of `assertion` attribute ([#619](https://github.com/avenga/couper/pull/619))

DOCKER.md

@@ -71,6 +71,7 @@ $ docker run avenga/couper run -watch -p 8081
 | COUPER_LOG_PARENT_FIELD              | `""` | An option for `json` log format to add all log fields as child properties. |
 | COUPER_LOG_PRETTY                    | `false` | Global option for `json` log format which pretty prints with basic key coloring. |
 | COUPER_LOG_TYPE_VALUE                | `couper_daemon` | Value for the runtime log field `type`. |
+| COUPER_SERVER_TIMING_HEADER          | `false` | If enabled, Couper includes an additional [Server-Timing](https://developer.mozilla.org/en-US/docs/Web/HTTP/Headers/Server-Timing) HTTP response header field detailing connection and transport relevant metrics for each backend request. |
 | COUPER_ACCESS_LOG_REQUEST_HEADERS    | `User-Agent, Accept, Referer` | A comma separated list of header names whose values should be logged. |
 | COUPER_ACCESS_LOG_RESPONSE_HEADERS   | `Cache-Control, Content-Encoding, Content-Type, Location` | A comma separated list of header names whose values should be logged. |
 | COUPER_ACCESS_LOG_TYPE_VALUE         | `couper_access` | Value for the log field `type`. |

command/run.go

@@ -213,6 +213,7 @@ func newFlagSet(settings *config.Settings, cmdName string) *flag.FlagSet {
 	set.StringVar(&settings.RequestIDClientHeader, "request-id-client-header", settings.RequestIDClientHeader, "-request-id-client-header Couper-Request-ID")
 	set.StringVar(&settings.RequestIDFormat, "request-id-format", settings.RequestIDFormat, "-request-id-format uuid4")
 	set.StringVar(&settings.SecureCookies, "secure-cookies", settings.SecureCookies, "-secure-cookies strip")
+	set.BoolVar(&settings.SendServerTimings, "send-server-timing-headers", settings.SendServerTimings, "-send-server-timing-headers")
 	set.BoolVar(&settings.TelemetryMetrics, "beta-metrics", settings.TelemetryMetrics, "-beta-metrics")
 	set.IntVar(&settings.TelemetryMetricsPort, "beta-metrics-port", settings.TelemetryMetricsPort, "-beta-metrics-port 9090")
 	set.StringVar(&settings.TelemetryMetricsEndpoint, "beta-metrics-endpoint", settings.TelemetryMetricsEndpoint, "-beta-metrics-endpoint [host:port]")

config/configload/backend.go

@@ -182,7 +182,7 @@ func setOAuth2Backend(helper *helper, parent *hclsyntax.Body) (*hclsyntax.Body,
 
 func checkTokenRequestLabels(trbs []*hclsyntax.Block, unique map[string]struct{}) error {
 	for _, trb := range trbs {
-		label := defaultNameLabel
+		label := config.DefaultNameLabel
 		dr := trb.DefRange()
 		r := &dr
 		if len(trb.Labels) > 0 {

config/configload/endpoint.go

@@ -64,7 +64,7 @@ func refineEndpoints(helper *helper, endpoints config.Endpoints, checkPathPatter
 
 		for _, proxyConfig := range ep.Proxies {
 			if proxyConfig.Name == "" {
-				proxyConfig.Name = defaultNameLabel
+				proxyConfig.Name = config.DefaultNameLabel
 			}
 
 			names[proxyConfig.Name] = proxyConfig.HCLBody()
@@ -86,7 +86,7 @@ func refineEndpoints(helper *helper, endpoints config.Endpoints, checkPathPatter
 			}
 
 			if wsEnabled {
-				if proxyConfig.Name != defaultNameLabel {
+				if proxyConfig.Name != config.DefaultNameLabel {
 					return errors.Configuration.Message("websockets attribute or block is only allowed in a 'default' proxy block")
 				}
 				if proxyRequestLabelRequired || ep.Response != nil {
@@ -106,7 +106,7 @@ func refineEndpoints(helper *helper, endpoints config.Endpoints, checkPathPatter
 
 		for _, reqConfig := range ep.Requests {
 			if reqConfig.Name == "" {
-				reqConfig.Name = defaultNameLabel
+				reqConfig.Name = config.DefaultNameLabel
 			}
 
 			names[reqConfig.Name] = reqConfig.HCLBody()
@@ -143,7 +143,7 @@ func refineEndpoints(helper *helper, endpoints config.Endpoints, checkPathPatter
 			}
 		}
 
-		if _, ok := names[defaultNameLabel]; checkPathPattern && !ok && ep.Response == nil {
+		if _, ok := names[config.DefaultNameLabel]; checkPathPattern && !ok && ep.Response == nil {
 			return newDiagErr(&subject, "Missing a 'default' proxy or request definition, or a response block")
 		}
 

config/configload/load.go

@@ -44,8 +44,6 @@ const (
 	spa             = "spa"
 	tls             = "tls"
 	tokenRequest    = "beta_token_request"
-	// defaultNameLabel maps the hcl label attr 'name'.
-	defaultNameLabel = "default"
 )
 
 var defaultsConfig *config.Defaults

config/configload/merge.go

@@ -7,6 +7,7 @@ import (
 	"sort"
 	"strings"
 
+	"github.com/avenga/couper/config"
 	"github.com/avenga/couper/eval"
 	"github.com/hashicorp/hcl/v2"
 	"github.com/hashicorp/hcl/v2/hclsyntax"
@@ -535,7 +536,7 @@ func mergeDefinitions(bodies []*hclsyntax.Body) (*hclsyntax.Block, map[string]*h
 
 							delete(innerBlock.Body.Attributes, "name")
 						} else {
-							innerBlock.Labels[0] = defaultNameLabel
+							innerBlock.Labels[0] = config.DefaultNameLabel
 						}
 
 						proxiesList[label] = innerBlock

config/const.go

@@ -0,0 +1,4 @@
+package config
+
+// DefaultNameLabel maps the hcl label attr 'name'.
+const DefaultNameLabel = "default"

config/request/context_key.go

@@ -32,6 +32,7 @@ const (
 	RoundTripName
 	RoundTripProxy
 	ServerName
+	ServerTimings
 	StartTime
 	TokenRequest
 	TokenRequestRetries

config/runtime/endpoint.go

@@ -177,17 +177,18 @@ func NewEndpointOptions(confCtx *hcl.EvalContext, endpointConf *config.Endpoint,
 	}
 
 	return &handler.EndpointOptions{
-		APIName:       apiName,
-		Context:       endpointConf.HCLBody(),
-		ErrorTemplate: errTpl,
-		LogPattern:    endpointConf.Pattern,
-		Proxies:       proxies,
-		ReqBodyLimit:  bodyLimit,
-		BufferOpts:    bufferOpts,
-		Requests:      requests,
-		Sequences:     sequences,
-		Response:      response,
-		ServerOpts:    serverOptions,
+		APIName:           apiName,
+		Context:           endpointConf.HCLBody(),
+		ErrorTemplate:     errTpl,
+		LogPattern:        endpointConf.Pattern,
+		Proxies:           proxies,
+		ReqBodyLimit:      bodyLimit,
+		BufferOpts:        bufferOpts,
+		Requests:          requests,
+		SendServerTimings: conf.Settings.SendServerTimings,
+		Sequences:         sequences,
+		Response:          response,
+		ServerOpts:        serverOptions,
 	}, nil
 }
 

config/settings.go

@@ -21,6 +21,7 @@ var defaultSettings = Settings{
 	RequestIDBackendHeader:   "Couper-Request-ID",
 	RequestIDClientHeader:    "Couper-Request-ID",
 	RequestIDFormat:          "common",
+	SendServerTimings:        false,
 	TelemetryMetricsEndpoint: otelCollectorEndpoint,
 	TelemetryMetricsExporter: "prometheus",
 	TelemetryMetricsPort:     9090, // default prometheus port
@@ -50,6 +51,7 @@ type Settings struct {
 	RequestIDClientHeader     string `hcl:"request_id_client_header,optional" docs:"HTTP header field which Couper uses to transport the {request.id} to the client" default:"Couper-Request-ID"`
 	RequestIDFormat           string `hcl:"request_id_format,optional" docs:"{\"common\"} or {\"uuid4\"}. If set to {\"uuid4\"} an RFC 4122 UUID is used for {request.id} and related log fields. " default:"common"`
 	SecureCookies             string `hcl:"secure_cookies,optional" docs:"{\"\"} or {\"strip\"}. If set to {\"strip\"}, the {Secure} flag is removed from all {Set-Cookie} HTTP header fields." default:"\u200C"`
+	SendServerTimings         bool   `hcl:"server_timing_header,optional" docs:"If enabled, Couper includes an additional [Server-Timing](https://developer.mozilla.org/en-US/docs/Web/HTTP/Headers/Server-Timing) HTTP response header field detailing connection and transport relevant metrics for each backend request."`
 	TLSDevProxy               List   `hcl:"https_dev_proxy,optional" docs:"TLS port mappings to define the TLS listen port and the target one. Self-signed certificates will be generated on the fly based on the given hostname. Certificates will be held in memory."`
 	TelemetryMetrics          bool   `hcl:"beta_metrics,optional" docs:"enables the Prometheus [metrics](/observation/metrics) exporter"`
 	TelemetryMetricsEndpoint  string `hcl:"beta_metrics_endpoint,optional" docs:"" default:""`

docs/website/content/2.configuration/0.command-line.md

@@ -92,6 +92,7 @@ DEBU[0000] loaded files … […/global.hcl …/conf/a.hcl …/conf/b.hcl …/co
 | `COUPER_BACKEND_LOG_TYPE_VALUE`        | `couper_backend` | Value for the log field `type`. |
 | `COUPER_LOG_PARENT_FIELD`              | `""` | An option for `json` log format to add all log fields as child properties. |
 | `COUPER_LOG_TYPE_VALUE`                | `couper_daemon` | Value for the runtime log field `type`. |
+| `COUPER_SERVER_TIMING_HEADER`          | `false` | If enabled, Couper includes an additional [Server-Timing](https://developer.mozilla.org/en-US/docs/Web/HTTP/Headers/Server-Timing) HTTP response header field detailing connection and transport relevant metrics for each backend request. |
 | `COUPER_TIMING_IDLE_TIMEOUT`           | `60s` | The maximum amount of time to wait for the next request on client connections when keep-alives are enabled. |
 | `COUPER_TIMING_READ_HEADER_TIMEOUT`    | `10s` | The amount of time allowed to read client request headers. |
 | `COUPER_TIMING_SHUTDOWN_DELAY`         | `0` | The amount of time the server is marked as unhealthy until calling server close finally. |

docs/website/content/2.configuration/4.block/settings.md

@@ -126,6 +126,12 @@ values: [
     "name": "secure_cookies",
     "type": "string"
   },
+  {
+    "default": "false",
+    "description": "If enabled, Couper includes an additional [Server-Timing](https://developer.mozilla.org/en-US/docs/Web/HTTP/Headers/Server-Timing) HTTP response header field detailing connection and transport relevant metrics for each backend request.",
+    "name": "server_timing_header",
+    "type": "bool"
+  },
   {
     "default": "false",
     "description": "whether to use the `X-Forwarded-Host` header as the request host",

handler/endpoint.go

@@ -6,6 +6,7 @@ import (
 	"net/http"
 	"runtime/debug"
 	"strconv"
+	"strings"
 	"sync"
 
 	"github.com/hashicorp/hcl/v2"
@@ -20,8 +21,11 @@ import (
 	"github.com/avenga/couper/handler/producer"
 	"github.com/avenga/couper/server/writer"
 	"github.com/avenga/couper/telemetry"
+	"github.com/avenga/couper/utils"
 )
 
+const serverTimingHeader = "Server-Timing"
+
 var _ http.Handler = &Endpoint{}
 var _ BodyLimit = &Endpoint{}
 
@@ -32,17 +36,18 @@ type Endpoint struct {
 }
 
 type EndpointOptions struct {
-	APIName        string
-	BufferOpts     eval.BufferOption
-	Context        *hclsyntax.Body
-	ErrorTemplate  *errors.Template
-	ErrorHandler   http.Handler
-	IsErrorHandler bool
-	IsJob          bool
-	LogHandlerKind string
-	LogPattern     string
-	ReqBodyLimit   int64
-	ServerOpts     *server.Options
+	APIName           string
+	BufferOpts        eval.BufferOption
+	Context           *hclsyntax.Body
+	ErrorTemplate     *errors.Template
+	ErrorHandler      http.Handler
+	IsErrorHandler    bool
+	IsJob             bool
+	LogHandlerKind    string
+	LogPattern        string
+	ReqBodyLimit      int64
+	SendServerTimings bool
+	ServerOpts        *server.Options
 
 	Proxies   producer.Roundtrip
 	Redirect  *producer.Redirect
@@ -167,6 +172,10 @@ func (e *Endpoint) ServeHTTP(rw http.ResponseWriter, req *http.Request) {
 		return
 	}
 
+	if e.opts.SendServerTimings {
+		rw.Header().Add(serverTimingHeader, getServerTimings(clientres.Header, beresps))
+	}
+
 	// copy/write like a reverseProxy
 	copyHeader(rw.Header(), clientres.Header)
 
@@ -186,6 +195,33 @@ func (e *Endpoint) ServeHTTP(rw http.ResponseWriter, req *http.Request) {
 	_ = clientres.Body.Close()
 }
 
+func getServerTimings(headers http.Header, beresps producer.ResultMap) string {
+	serverTimings := make(utils.ServerTimings)
+
+	for _, h := range headers.Values(serverTimingHeader) {
+		utils.CollectMetricNames(h, serverTimings)
+	}
+
+	for _, r := range beresps {
+		if r == nil || r.Beresp == nil {
+			continue
+		}
+
+		timings, _ := r.Beresp.Request.Context().Value(request.ServerTimings).(utils.ServerTimings)
+
+		utils.MergeMetrics(timings, serverTimings)
+	}
+
+	var parts []string
+	for k, v := range serverTimings {
+		if v != "" {
+			parts = append(parts, k+";"+v)
+		}
+	}
+
+	return strings.Join(parts, ", ")
+}
+
 // withContext binds some endpoint context related values for logging and buffer purposes.
 func (e *Endpoint) withContext(req *http.Request) context.Context {
 	reqCtx := context.WithValue(req.Context(), request.Endpoint, e.opts.LogPattern)

logging/upstream_log.go

@@ -3,6 +3,7 @@ package logging
 import (
 	"context"
 	"crypto/tls"
+	"fmt"
 	"net/http"
 	"net/http/httptrace"
 	"net/url"
@@ -12,11 +13,13 @@ import (
 	"github.com/sirupsen/logrus"
 	"github.com/zclconf/go-cty/cty"
 
+	"github.com/avenga/couper/config"
 	"github.com/avenga/couper/config/env"
 	"github.com/avenga/couper/config/request"
 	"github.com/avenga/couper/errors"
 	"github.com/avenga/couper/handler/validation"
 	"github.com/avenga/couper/internal/seetie"
+	"github.com/avenga/couper/utils"
 	"github.com/hashicorp/hcl/v2"
 )
 
@@ -94,6 +97,7 @@ func (u *UpstreamLog) RoundTrip(req *http.Request) (*http.Response, error) {
 
 	close(logCtxCh)
 
+	// FIXME: Can host be empty?
 	if outreq.Host != "" {
 		requestFields["origin"] = outreq.Host
 		requestFields["host"], requestFields["port"] = splitHostPort(outreq.Host)
@@ -149,17 +153,40 @@ func (u *UpstreamLog) RoundTrip(req *http.Request) (*http.Response, error) {
 		fields["validation"] = validationErrors
 	}
 
+	serverTimingsVal := make(utils.ServerTimings)
+	serverTimingsKey := ""
+
+	// For test cases: "backend" is sometimes not set
+	if u.log != nil {
+		if key, exists := u.log.Data["backend"]; exists {
+			serverTimingsKey = key.(string)
+		}
+	}
+
+	if name, ok := requestFields["name"].(string); ok && name != config.DefaultNameLabel {
+		serverTimingsKey += "_" + name
+	}
+
 	timingResults := Fields{
 		"total": RoundMS(rtDone.Sub(rtStart)),
 	}
+	serverTimingsVal[fmt.Sprintf(`%s_%s`, serverTimingsKey, "total")] = fmt.Sprintf(`dur=%.3f`, timingResults["total"])
+
 	timingsMu.RLock()
 	for f, v := range timings { // clone
 		timingResults[f] = v
+
+		serverTimingsVal[fmt.Sprintf(`%s_%s`, serverTimingsKey, f)] = fmt.Sprintf(`dur=%.3f`, v)
 	}
 	timingsMu.RUnlock()
+
 	fields["timings"] = timingResults
 	//timings["ttlb"] = RoundMS(rtDone.Sub(timeTTFB)) // TODO: depends on stream or buffer
 
+	if beresp != nil {
+		beresp.Request = outreq.WithContext(context.WithValue(outreq.Context(), request.ServerTimings, serverTimingsVal))
+	}
+
 	entry := u.log.
 		WithFields(logrus.Fields(fields)).
 		WithContext(outreq.Context()).

server/http_test.go

@@ -14,6 +14,7 @@ import (
 	"os"
 	"path"
 	"regexp"
+	"sort"
 	"strconv"
 	"strings"
 	"sync"
@@ -917,6 +918,50 @@ func TestHTTPServer_RateLimiterBlock(t *testing.T) {
 	mu.Unlock()
 }
 
+func TestHTTPServer_ServerTiming(t *testing.T) {
+	helper := test.New(t)
+	client := newClient()
+
+	confPath1 := "testdata/integration/http/01_couper.hcl"
+	shutdown1, _ := newCouper(confPath1, test.New(t))
+	defer shutdown1()
+
+	confPath2 := "testdata/integration/http/02_couper.hcl"
+	shutdown2, _ := newCouper(confPath2, test.New(t))
+	defer shutdown2()
+
+	req, err := http.NewRequest(http.MethodGet, "http://anyserver:9090/", nil)
+	helper.Must(err)
+
+	res, err := client.Do(req)
+	helper.Must(err)
+
+	headers := res.Header.Values("Server-Timing")
+	if l := len(headers); l != 2 {
+		t.Fatalf("Unexpected number of headers: %d", l)
+	}
+
+	dataCouper1 := strings.Split(headers[0], ", ")
+	dataCouper2 := strings.Split(headers[1], ", ")
+
+	sort.Strings(dataCouper1)
+	sort.Strings(dataCouper2)
+
+	if len(dataCouper1) != 4 || len(dataCouper2) != 6 {
+		t.Fatal("Unexpected number of metrics")
+	}
+
+	exp1 := regexp.MustCompile(`b1_dns_[0-9a-f]{6};dur=\d+(.\d)* b1_tcp_[0-9a-f]{6};dur=\d+(.\d)* b1_total_[0-9a-f]{6};dur=\d+(.\d)* b1_ttfb_[0-9a-f]{6};dur=\d+(.\d)*`)
+	if s := strings.Join(dataCouper1, " "); !exp1.MatchString(s) {
+		t.Errorf("Unexpected header from 'first' Couper: %s", s)
+	}
+
+	exp2 := regexp.MustCompile(`b1_tcp;dur=\d+(.\d)* b1_total;dur=\d+(.\d)* b1_ttfb;dur=\d+(.\d)* b2_REQ_tcp;dur=\d+(.\d)* b2_REQ_total;dur=\d+(.\d)* b2_REQ_ttfb;dur=\d+(.\d)*`)
+	if s := strings.Join(dataCouper2, " "); !exp2.MatchString(s) {
+		t.Errorf("Unexpected header from 'second' Couper: %s", s)
+	}
+}
+
 func TestHTTPServer_CVE_2022_2880(t *testing.T) {
 	helper := test.New(t)
 	client := newClient()