diff --git a/exchange/bidder.go b/exchange/bidder.go index a230041de87..cba79eee984 100644 --- a/exchange/bidder.go +++ b/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) } diff --git a/exchange/bidder_test.go b/exchange/bidder_test.go index 4f207cf5a65..e3b2a0313a4 100644 --- a/exchange/bidder_test.go +++ b/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 diff --git a/pbsmetrics/config/metrics.go b/pbsmetrics/config/metrics.go index 7fd048e1b2b..b97654a672b 100644 --- a/pbsmetrics/config/metrics.go +++ b/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) { } diff --git a/pbsmetrics/go_metrics.go b/pbsmetrics/go_metrics.go index 180b12295c6..4d5dd3cb43c 100644 --- a/pbsmetrics/go_metrics.go +++ b/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) { diff --git a/pbsmetrics/go_metrics_test.go b/pbsmetrics/go_metrics_test.go index f4d62c46c12..dd09c3ec1eb 100644 --- a/pbsmetrics/go_metrics_test.go +++ b/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" diff --git a/pbsmetrics/metrics.go b/pbsmetrics/metrics.go index 95fa13cc192..2397364bb04 100644 --- a/pbsmetrics/metrics.go +++ b/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. diff --git a/pbsmetrics/metrics_mock.go b/pbsmetrics/metrics_mock.go index 6871f92bf05..e8c0ee1350e 100644 --- a/pbsmetrics/metrics_mock.go +++ b/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) diff --git a/pbsmetrics/prometheus/prometheus.go b/pbsmetrics/prometheus/prometheus.go index 2086c935710..a7aabd1fe76 100644 --- a/pbsmetrics/prometheus/prometheus.go +++ b/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), diff --git a/pbsmetrics/prometheus/prometheus_test.go b/pbsmetrics/prometheus/prometheus_test.go index 5d6ad3912bd..bdd1bc7a77a 100644 --- a/pbsmetrics/prometheus/prometheus_test.go +++ b/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 {