Add TLS Handshake connection metrics (prebid#1613)

exchange/bidder.go

@@ -3,6 +3,7 @@ package exchange
 import (
 	"bytes"
 	"context"
+	"crypto/tls"
 	"encoding/json"
 	"errors"
 	"fmt"
@@ -445,7 +446,7 @@ type httpCallInfo struct {
 // endpoint is established, we can keep track of whether the connection was newly created, reused, and
 // the time from the connection request, to the connection creation.
 func (bidder *bidderAdapter) addClientTrace(ctx context.Context) context.Context {
-	var connStart, dnsStart time.Time
+	var connStart, dnsStart, tlsStart time.Time
 
 	trace := &httptrace.ClientTrace{
 		// GetConn is called before a connection is created or retrieved from an idle pool
@@ -468,6 +469,16 @@ func (bidder *bidderAdapter) addClientTrace(ctx context.Context) context.Context
 
 			bidder.me.RecordDNSTime(dnsLookupTime)
 		},
+
+		TLSHandshakeStart: func() {
+			tlsStart = time.Now()
+		},
+
+		TLSHandshakeDone: func(tls.ConnectionState, error) {
+			tlsHandshakeTime := time.Now().Sub(tlsStart)
+
+			bidder.me.RecordTLSHandshakeTime(tlsHandshakeTime)
+		},
 	}
 	return httptrace.WithClientTrace(ctx, trace)
 }

exchange/bidder_test.go

@@ -3,6 +3,7 @@ package exchange
 import (
 	"bytes"
 	"context"
+	"crypto/tls"
 	"encoding/json"
 	"errors"
 	"fmt"
@@ -1238,21 +1239,36 @@ func TestCallRecordAdapterConnections(t *testing.T) {
 type DNSDoneTripper struct{}
 
 func (DNSDoneTripper) RoundTrip(req *http.Request) (*http.Response, error) {
-	//Access the httptrace.ClientTrace
+	// Access the httptrace.ClientTrace
 	trace := httptrace.ContextClientTrace(req.Context())
-
-	//Force DNSDone call defined in exchange/bidder.go
+	// Call the DNSDone method on the client trace
 	trace.DNSDone(httptrace.DNSDoneInfo{})
 
 	resp := &http.Response{
 		StatusCode: 200,
-		Header:     map[string][]string{"Location": {"http://www.example.com/"}},
 		Body:       ioutil.NopCloser(strings.NewReader("postBody")),
 	}
+
+	return resp, nil
+}
+
+type TLSHandshakeTripper struct{}
+
+func (TLSHandshakeTripper) RoundTrip(req *http.Request) (*http.Response, error) {
+	// Access the httptrace.ClientTrace
+	trace := httptrace.ContextClientTrace(req.Context())
+	// Call the TLSHandshakeDone method on the client trace
+	trace.TLSHandshakeDone(tls.ConnectionState{}, nil)
+
+	resp := &http.Response{
+		StatusCode: 200,
+		Body:       ioutil.NopCloser(strings.NewReader("postBody")),
+	}
+
 	return resp, nil
 }
 
-func TestCallRecordRecordDNSTime(t *testing.T) {
+func TestCallRecordDNSTime(t *testing.T) {
 	// setup a mock metrics engine and its expectation
 	metricsMock := &pbsmetrics.MetricsEngineMock{}
 	metricsMock.Mock.On("RecordDNSTime", mock.Anything).Return()
@@ -1273,6 +1289,27 @@ func TestCallRecordRecordDNSTime(t *testing.T) {
 	metricsMock.AssertExpectations(t)
 }
 
+func TestCallRecordTLSHandshakeTime(t *testing.T) {
+	// setup a mock metrics engine and its expectation
+	metricsMock := &pbsmetrics.MetricsEngineMock{}
+	metricsMock.Mock.On("RecordTLSHandshakeTime", mock.Anything).Return()
+
+	// Instantiate the bidder that will send the request. We'll make sure to use an
+	// http.Client that runs our mock RoundTripper so DNSDone(httptrace.DNSDoneInfo{})
+	// gets called
+	bidder := &bidderAdapter{
+		Bidder: &mixedMultiBidder{},
+		Client: &http.Client{Transport: TLSHandshakeTripper{}},
+		me:     metricsMock,
+	}
+
+	// Run test
+	bidder.doRequest(context.Background(), &adapters.RequestData{Method: "POST", Uri: "http://www.example.com/"})
+
+	// Tried one or another, none seem to work without panicking
+	metricsMock.AssertExpectations(t)
+}
+
 func TestTimeoutNotificationOff(t *testing.T) {
 	respBody := "{\"bid\":false}"
 	respStatus := 200

pbsmetrics/config/metrics.go

@@ -147,6 +147,12 @@ func (me *MultiMetricsEngine) RecordDNSTime(dnsLookupTime time.Duration) {
 	}
 }
 
+func (me *MultiMetricsEngine) RecordTLSHandshakeTime(tlsHandshakeTime time.Duration) {
+	for _, thisME := range *me {
+		thisME.RecordTLSHandshakeTime(tlsHandshakeTime)
+	}
+}
+
 // RecordAdapterBidReceived across all engines
 func (me *MultiMetricsEngine) RecordAdapterBidReceived(labels pbsmetrics.AdapterLabels, bidType openrtb_ext.BidType, hasAdm bool) {
 	for _, thisME := range *me {
@@ -289,6 +295,10 @@ func (me *DummyMetricsEngine) RecordAdapterConnections(bidderName openrtb_ext.Bi
 func (me *DummyMetricsEngine) RecordDNSTime(dnsLookupTime time.Duration) {
 }
 
+// RecordTLSHandshakeTime as a noop
+func (me *DummyMetricsEngine) RecordTLSHandshakeTime(tlsHandshakeTime time.Duration) {
+}
+
 // RecordAdapterBidReceived as a noop
 func (me *DummyMetricsEngine) RecordAdapterBidReceived(labels pbsmetrics.AdapterLabels, bidType openrtb_ext.BidType, hasAdm bool) {
 }

pbsmetrics/go_metrics.go

@@ -31,6 +31,7 @@ type Metrics struct {
 	StoredImpCacheMeter            map[CacheResult]metrics.Meter
 	AccountCacheMeter              map[CacheResult]metrics.Meter
 	DNSLookupTimer                 metrics.Timer
+	TLSHandshakeTimer              metrics.Timer
 
 	// Metrics for OpenRTB requests specifically. So we can track what % of RequestsMeter are OpenRTB
 	// and know when legacy requests have been abandoned.
@@ -127,6 +128,7 @@ func NewBlankMetrics(registry metrics.Registry, exchanges []openrtb_ext.BidderNa
 		NoCookieMeter:                  blankMeter,
 		RequestTimer:                   blankTimer,
 		DNSLookupTimer:                 blankTimer,
+		TLSHandshakeTimer:              blankTimer,
 		RequestsQueueTimer:             make(map[RequestType]map[bool]metrics.Timer),
 		PrebidCacheRequestTimerSuccess: blankTimer,
 		PrebidCacheRequestTimerError:   blankTimer,
@@ -227,6 +229,7 @@ func NewMetrics(registry metrics.Registry, exchanges []openrtb_ext.BidderName, d
 	newMetrics.AppRequestMeter = metrics.GetOrRegisterMeter("app_requests", registry)
 	newMetrics.RequestTimer = metrics.GetOrRegisterTimer("request_time", registry)
 	newMetrics.DNSLookupTimer = metrics.GetOrRegisterTimer("dns_lookup_time", registry)
+	newMetrics.TLSHandshakeTimer = metrics.GetOrRegisterTimer("tls_handshake_time", registry)
 	newMetrics.PrebidCacheRequestTimerSuccess = metrics.GetOrRegisterTimer("prebid_cache_request_time.ok", registry)
 	newMetrics.PrebidCacheRequestTimerError = metrics.GetOrRegisterTimer("prebid_cache_request_time.err", registry)
 
@@ -542,6 +545,10 @@ func (me *Metrics) RecordDNSTime(dnsLookupTime time.Duration) {
 	me.DNSLookupTimer.Update(dnsLookupTime)
 }
 
+func (me *Metrics) RecordTLSHandshakeTime(tlsHandshakeTime time.Duration) {
+	me.TLSHandshakeTimer.Update(tlsHandshakeTime)
+}
+
 // RecordAdapterBidReceived implements a part of the MetricsEngine interface.
 // This tracks how many bids from each Bidder use `adm` vs. `nurl.
 func (me *Metrics) RecordAdapterBidReceived(labels AdapterLabels, bidType openrtb_ext.BidType, hasAdm bool) {

pbsmetrics/go_metrics_test.go

@@ -209,6 +209,33 @@ func TestRecordDNSTime(t *testing.T) {
 	}
 }
 
+func TestRecordTLSHandshakeTime(t *testing.T) {
+	testCases := []struct {
+		description          string
+		tLSHandshakeDuration time.Duration
+		expectedDuration     time.Duration
+	}{
+		{
+			description:          "Five second TLS handshake time",
+			tLSHandshakeDuration: time.Second * 5,
+			expectedDuration:     time.Second * 5,
+		},
+		{
+			description:          "Zero TLS handshake time",
+			tLSHandshakeDuration: time.Duration(0),
+			expectedDuration:     time.Duration(0),
+		},
+	}
+	for _, test := range testCases {
+		registry := metrics.NewRegistry()
+		m := NewMetrics(registry, []openrtb_ext.BidderName{openrtb_ext.BidderAppnexus}, config.DisabledMetrics{AccountAdapterDetails: true})
+
+		m.RecordTLSHandshakeTime(test.tLSHandshakeDuration)
+
+		assert.Equal(t, test.expectedDuration.Nanoseconds(), m.TLSHandshakeTimer.Sum(), test.description)
+	}
+}
+
 func TestRecordAdapterConnections(t *testing.T) {
 	var fakeBidder openrtb_ext.BidderName = "fooAdvertising"
 

pbsmetrics/metrics.go

@@ -339,6 +339,7 @@ type MetricsEngine interface {
 	RecordAdapterRequest(labels AdapterLabels)
 	RecordAdapterConnections(adapterName openrtb_ext.BidderName, connWasReused bool, connWaitTime time.Duration)
 	RecordDNSTime(dnsLookupTime time.Duration)
+	RecordTLSHandshakeTime(tlsHandshakeTime time.Duration)
 	RecordAdapterPanic(labels AdapterLabels)
 	// This records whether or not a bid of a particular type uses `adm` or `nurl`.
 	// Since the legacy endpoints don't have a bid type, it can only count bids from OpenRTB and AMP.

pbsmetrics/metrics_mock.go

@@ -72,6 +72,10 @@ func (me *MetricsEngineMock) RecordDNSTime(dnsLookupTime time.Duration) {
 	me.Called(dnsLookupTime)
 }
 
+func (me *MetricsEngineMock) RecordTLSHandshakeTime(tlsHandshakeTime time.Duration) {
+	me.Called(tlsHandshakeTime)
+}
+
 // RecordAdapterBidReceived mock
 func (me *MetricsEngineMock) RecordAdapterBidReceived(labels AdapterLabels, bidType openrtb_ext.BidType, hasAdm bool) {
 	me.Called(labels, bidType, hasAdm)

pbsmetrics/prometheus/prometheus.go

@@ -41,6 +41,7 @@ type Metrics struct {
 	storedVideoErrors            *prometheus.CounterVec
 	timeoutNotifications         *prometheus.CounterVec
 	dnsLookupTimer               prometheus.Histogram
+	tlsHandhakeTimer             prometheus.Histogram
 	privacyCCPA                  *prometheus.CounterVec
 	privacyCOPPA                 *prometheus.CounterVec
 	privacyLMT                   *prometheus.CounterVec
@@ -257,6 +258,11 @@ func NewMetrics(cfg config.PrometheusMetrics, disabledMetrics config.DisabledMet
 		"Seconds to resolve DNS",
 		standardTimeBuckets)
 
+	metrics.tlsHandhakeTimer = newHistogram(cfg, metrics.Registry,
+		"tls_handshake_time",
+		"Seconds to perform TLS Handshake",
+		standardTimeBuckets)
+
 	metrics.privacyCCPA = newCounter(cfg, metrics.Registry,
 		"privacy_ccpa",
 		"Count of total requests to Prebid Server where CCPA was provided by source and opt-out .",
@@ -554,6 +560,10 @@ func (m *Metrics) RecordDNSTime(dnsLookupTime time.Duration) {
 	m.dnsLookupTimer.Observe(dnsLookupTime.Seconds())
 }
 
+func (m *Metrics) RecordTLSHandshakeTime(tlsHandshakeTime time.Duration) {
+	m.tlsHandhakeTimer.Observe(tlsHandshakeTime.Seconds())
+}
+
 func (m *Metrics) RecordAdapterPanic(labels pbsmetrics.AdapterLabels) {
 	m.adapterPanics.With(prometheus.Labels{
 		adapterLabel: string(labels.Adapter),

pbsmetrics/prometheus/prometheus_test.go

@@ -1197,6 +1197,39 @@ func TestRecordDNSTime(t *testing.T) {
 	}
 }
 
+func TestRecordTLSHandshakeTime(t *testing.T) {
+	testCases := []struct {
+		description          string
+		tLSHandshakeDuration time.Duration
+		expectedDuration     float64
+		expectedCount        uint64
+	}{
+		{
+			description:          "Five second DNS lookup time",
+			tLSHandshakeDuration: time.Second * 5,
+			expectedDuration:     5,
+			expectedCount:        1,
+		},
+		{
+			description:          "Zero DNS lookup time",
+			tLSHandshakeDuration: 0,
+			expectedDuration:     0,
+			expectedCount:        1,
+		},
+	}
+	for i, test := range testCases {
+		pm := createMetricsForTesting()
+		pm.RecordTLSHandshakeTime(test.tLSHandshakeDuration)
+
+		m := dto.Metric{}
+		pm.tlsHandhakeTimer.Write(&m)
+		histogram := *m.GetHistogram()
+
+		assert.Equal(t, test.expectedCount, histogram.GetSampleCount(), "[%d] Incorrect number of histogram entries. Desc: %s\n", i, test.description)
+		assert.Equal(t, test.expectedDuration, histogram.GetSampleSum(), "[%d] Incorrect number of histogram cumulative values. Desc: %s\n", i, test.description)
+	}
+}
+
 func TestRecordAdapterConnections(t *testing.T) {
 
 	type testIn struct {