Add backend and connection metrics / traces

handler/transport/backend.go

@@ -36,6 +36,7 @@ var _ http.RoundTripper = &Backend{}
 // Backend represents the transport configuration.
 type Backend struct {
 	context          hcl.Body
+	logEntry         *logrus.Entry
 	name             string
 	openAPIValidator *validation.OpenAPI
 	options          *BackendOptions
@@ -61,6 +62,7 @@ func NewBackend(ctx hcl.Body, tc *Config, opts *BackendOptions, log *logrus.Entr
 
 	backend := &Backend{
 		context:          ctx,
+		logEntry:         logEntry,
 		openAPIValidator: openAPI,
 		options:          opts,
 		transportConf:    tc,
@@ -195,7 +197,7 @@ func (b *Backend) openAPIValidate(req *http.Request, tc *Config, deadlineErr <-c
 }
 
 func (b *Backend) innerRoundTrip(req *http.Request, tc *Config, deadlineErr <-chan error) (*http.Response, error) {
-	t := Get(tc)
+	t := Get(tc, b.logEntry)
 	beresp, err := t.RoundTrip(req)
 
 	if err != nil {

handler/transport/connection.go

@@ -0,0 +1,120 @@
+package transport
+
+import (
+	"context"
+	"crypto/tls"
+	"net"
+	"sync"
+	"time"
+
+	"github.com/sirupsen/logrus"
+	"go.opentelemetry.io/otel/attribute"
+	"go.opentelemetry.io/otel/metric"
+	"go.opentelemetry.io/otel/metric/global"
+
+	"github.com/avenga/couper/config/request"
+)
+
+const (
+	MetricConnections              = "connections_count"
+	MetricConnectionsTotal         = "connections_total_count"
+	MetricConnectionsLifetimeTotal = "connections_lifetime_total"
+
+	eventOpen  = "open"
+	eventClose = "close"
+)
+
+// OriginConn wraps the original net.Conn created by net.DialContext or transport.DialTLS for debug purposes.
+type OriginConn struct {
+	net.Conn
+
+	connClosedMu sync.Mutex
+	connClosed   bool
+
+	conf *Config
+
+	createdAt    time.Time
+	initialReqID string
+	labels       []attribute.KeyValue
+	log          *logrus.Entry
+	tlsState     *tls.ConnectionState
+}
+
+// NewOriginConn creates a new wrapper with logging context.
+func NewOriginConn(ctx context.Context, conn net.Conn, conf *Config, entry *logrus.Entry) *OriginConn {
+	backendName := "default"
+	if conf.BackendName != "" {
+		backendName = conf.BackendName
+	}
+	o := &OriginConn{
+		Conn:         conn,
+		conf:         conf,
+		createdAt:    time.Now(),
+		initialReqID: ctx.Value(request.UID).(string),
+		labels: []attribute.KeyValue{
+			attribute.String("origin", conf.Origin),
+			attribute.String("host", conf.Hostname),
+			attribute.String("backend", backendName),
+		},
+		log:      entry,
+		tlsState: nil,
+	}
+
+	if tlsConn, ok := conn.(*tls.Conn); ok {
+		state := tlsConn.ConnectionState()
+		o.tlsState = &state
+	}
+	entry.WithFields(o.logFields(eventOpen)).Debug()
+
+	meter := global.Meter("couper/connection")
+
+	counter := metric.Must(meter).NewInt64Counter(MetricConnectionsTotal)
+	gauge := metric.Must(meter).NewFloat64UpDownCounter(MetricConnections)
+	meter.RecordBatch(ctx, o.labels,
+		counter.Measurement(1),
+		gauge.Measurement(1),
+	)
+	return o
+}
+
+func (o *OriginConn) logFields(event string) logrus.Fields {
+	fields := logrus.Fields{
+		"event":       event,
+		"initial_uid": o.initialReqID,
+		"localAddr":   o.LocalAddr().String(),
+		"origin":      o.conf.Origin,
+		"remoteAddr":  o.RemoteAddr().String(),
+	}
+
+	var d time.Duration
+	if event == eventClose {
+		d = time.Now().Sub(o.createdAt) / time.Millisecond
+
+		meter := global.Meter("couper/connection")
+		counter := metric.Must(meter).NewFloat64Counter(MetricConnectionsLifetimeTotal)
+		meter.RecordBatch(context.Background(), o.labels, counter.Measurement(float64(d)))
+		fields["lifetime"] = d
+	}
+	return logrus.Fields{
+		"connection": fields,
+	}
+}
+
+func (o *OriginConn) Close() error {
+	o.connClosedMu.Lock()
+	if o.connClosed {
+		o.connClosedMu.Unlock()
+		return nil
+	}
+	o.connClosed = true
+	o.connClosedMu.Unlock()
+
+	o.log.WithFields(o.logFields(eventClose)).Debug()
+
+	meter := global.Meter("couper/connection")
+	gauge := metric.Must(meter).NewFloat64UpDownCounter(MetricConnections)
+	meter.RecordBatch(context.Background(), o.labels,
+		gauge.Measurement(-1),
+	)
+	return o.Conn.Close()
+}

handler/transport/transport.go

@@ -11,6 +11,11 @@ import (
 	"sync"
 	"time"
 
+	"github.com/sirupsen/logrus"
+	"go.opentelemetry.io/otel/attribute"
+	"go.opentelemetry.io/otel/trace"
+
+	"github.com/avenga/couper/telemetry"
 	"golang.org/x/net/http/httpproxy"
 )
 
@@ -37,7 +42,7 @@ type Config struct {
 }
 
 // Get creates a new <*http.Transport> object by the given <*Config>.
-func Get(conf *Config) *http.Transport {
+func Get(conf *Config, log *logrus.Entry) *http.Transport {
 	key := conf.hash()
 
 	transport, ok := transports.Load(key)
@@ -68,25 +73,31 @@ func Get(conf *Config) *http.Transport {
 			proxyFunc = http.ProxyFromEnvironment
 		}
 
-		// This is the documented way to disable http2. However if a custom tls.Config or
+		// This is the documented way to disable http2. However, if a custom tls.Config or
 		// DialContext is used h2 will also be disabled. To enable h2 the transport must be
 		// explicitly configured, this can be done with the 'ForceAttemptHTTP2' below.
 		var nextProto map[string]func(authority string, c *tls.Conn) http.RoundTripper
 		if !conf.HTTP2 {
 			nextProto = make(map[string]func(authority string, c *tls.Conn) http.RoundTripper)
 		}
 
+		logEntry := log.WithField("type", "couper_connection")
+
 		transport = &http.Transport{
 			DialContext: func(ctx context.Context, network, addr string) (net.Conn, error) {
 				address := addr
 				if proxyFunc == nil {
 					address = conf.Origin
-				} // Otherwise proxy connect will use this dial method and addr could be a proxy one.
-				conn, err := d.DialContext(ctx, network, address)
+				} // Otherwise, proxy connect will use this dial method and addr could be a proxy one.
+
+				stx, span := telemetry.NewSpanFromContext(ctx, "connect", trace.WithAttributes(attribute.String("couper.address", addr)))
+				defer span.End()
+
+				conn, err := d.DialContext(stx, network, address)
 				if err != nil {
 					return nil, fmt.Errorf("connecting to %s %q failed: %w", conf.BackendName, conf.Origin, err)
 				}
-				return conn, nil
+				return NewOriginConn(stx, conn, conf, logEntry), nil
 			},
 			DisableCompression:    true,
 			DisableKeepAlives:     conf.DisableConnectionReuse,