Add metric for tmax timeout exceed count (#2892)

Co-authored-by: oh0387 <[email protected]>
Co-authored-by: Onkar Hanumante <[email protected]>

exchange/bidder.go

@@ -548,6 +548,7 @@ func (bidder *bidderAdapter) doRequestImpl(ctx context.Context, req *adapters.Re
 
 	if tmaxAdjustments != nil && tmaxAdjustments.IsEnforced {
 		if hasShorterDurationThanTmax(&bidderTmaxCtx{ctx}, *tmaxAdjustments) {
+			bidder.me.RecordTMaxTimeout()
 			return &httpCallInfo{
 				request: req,
 				err:     errTmaxTimeout,

exchange/bidder_test.go

@@ -3262,3 +3262,57 @@ func TestDoRequestImplWithTmax(t *testing.T) {
 		test.assertFn(httpCallInfo.err)
 	}
 }
+
+func TestDoRequestImplWithTmaxTimeout(t *testing.T) {
+	respStatus := 200
+	respBody := "{\"bid\":false}"
+	server := httptest.NewServer(mockHandler(respStatus, "getBody", respBody))
+	defer server.Close()
+	requestStartTime := time.Date(2023, 1, 1, 0, 0, 0, 0, time.UTC)
+
+	bidRequest := adapters.RequestData{
+		Method: "POST",
+		Uri:    server.URL,
+		Body:   []byte(`{"id":"this-id","app":{"publisher":{"id":"pub-id"}}}`),
+	}
+
+	metricsMock := &metrics.MetricsEngineMock{}
+	metricsMock.On("RecordOverheadTime", metrics.PreBidder, mock.Anything).Once()
+	metricsMock.On("RecordTMaxTimeout").Once()
+
+	bidderAdapter := bidderAdapter{
+		me:     metricsMock,
+		Client: server.Client(),
+	}
+	logger := func(msg string, args ...interface{}) {}
+
+	tests := []struct {
+		ctxDeadline     time.Time
+		description     string
+		tmaxAdjustments *TmaxAdjustmentsPreprocessed
+		assertFn        func(err error)
+	}{
+		{
+			ctxDeadline:     time.Date(2023, 1, 1, 0, 0, 0, 0, time.UTC),
+			description:     "returns-tmax-timeout-error",
+			tmaxAdjustments: &TmaxAdjustmentsPreprocessed{IsEnforced: true, PBSResponsePreparationDuration: 100, BidderNetworkLatencyBuffer: 10, BidderResponseDurationMin: 5000},
+			assertFn:        func(err error) { assert.Equal(t, errTmaxTimeout, err) },
+		},
+	}
+	for _, test := range tests {
+		var (
+			ctx      context.Context
+			cancelFn context.CancelFunc
+		)
+
+		if test.ctxDeadline.IsZero() {
+			ctx = context.Background()
+		} else {
+			ctx, cancelFn = context.WithDeadline(context.Background(), test.ctxDeadline)
+			defer cancelFn()
+		}
+
+		httpCallInfo := bidderAdapter.doRequestImpl(ctx, &bidRequest, logger, requestStartTime, test.tmaxAdjustments)
+		test.assertFn(httpCallInfo.err)
+	}
+}

metrics/config/metrics.go

@@ -80,6 +80,12 @@ func (me *MultiMetricsEngine) RecordConnectionAccept(success bool) {
 	}
 }
 
+func (me *MultiMetricsEngine) RecordTMaxTimeout() {
+	for _, thisME := range *me {
+		thisME.RecordTMaxTimeout()
+	}
+}
+
 func (me *MultiMetricsEngine) RecordConnectionClose(success bool) {
 	for _, thisME := range *me {
 		thisME.RecordConnectionClose(success)
@@ -391,6 +397,10 @@ func (me *NilMetricsEngine) RecordRequest(labels metrics.Labels) {
 func (me *NilMetricsEngine) RecordConnectionAccept(success bool) {
 }
 
+// RecordTMaxTimeout as a noop
+func (me *NilMetricsEngine) RecordTMaxTimeout() {
+}
+
 // RecordConnectionClose as a noop
 func (me *NilMetricsEngine) RecordConnectionClose(success bool) {
 }

metrics/go_metrics.go

@@ -14,6 +14,7 @@ import (
 type Metrics struct {
 	MetricsRegistry                metrics.Registry
 	ConnectionCounter              metrics.Counter
+	TMaxTimeoutCounter             metrics.Counter
 	ConnectionAcceptErrorMeter     metrics.Meter
 	ConnectionCloseErrorMeter      metrics.Meter
 	ImpMeter                       metrics.Meter
@@ -288,6 +289,7 @@ func getModuleNames(moduleStageNames map[string][]string) []string {
 func NewMetrics(registry metrics.Registry, exchanges []openrtb_ext.BidderName, disableAccountMetrics config.DisabledMetrics, syncerKeys []string, moduleStageNames map[string][]string) *Metrics {
 	newMetrics := NewBlankMetrics(registry, exchanges, disableAccountMetrics, moduleStageNames)
 	newMetrics.ConnectionCounter = metrics.GetOrRegisterCounter("active_connections", registry)
+	newMetrics.TMaxTimeoutCounter = metrics.GetOrRegisterCounter("tmax_timeout", registry)
 	newMetrics.ConnectionAcceptErrorMeter = metrics.GetOrRegisterMeter("connection_accept_errors", registry)
 	newMetrics.ConnectionCloseErrorMeter = metrics.GetOrRegisterMeter("connection_close_errors", registry)
 	newMetrics.ImpMeter = metrics.GetOrRegisterMeter("imps_requested", registry)
@@ -713,6 +715,10 @@ func (me *Metrics) RecordConnectionAccept(success bool) {
 	}
 }
 
+func (m *Metrics) RecordTMaxTimeout() {
+	m.TMaxTimeoutCounter.Inc(1)
+}
+
 func (me *Metrics) RecordConnectionClose(success bool) {
 	if success {
 		me.ConnectionCounter.Dec(1)

metrics/go_metrics_test.go

@@ -84,6 +84,7 @@ func TestNewMetrics(t *testing.T) {
 	ensureContains(t, registry, "request_over_head_time.make-auction-response", m.OverheadTimer[MakeAuctionResponse])
 	ensureContains(t, registry, "request_over_head_time.make-bidder-requests", m.OverheadTimer[MakeBidderRequests])
 	ensureContains(t, registry, "bidder_server_response_time_seconds", m.BidderServerResponseTimer)
+	ensureContains(t, registry, "tmax_timeout", m.TMaxTimeoutCounter)
 
 	for module, stages := range moduleStageNames {
 		for _, stage := range stages {

metrics/metrics.go

@@ -421,6 +421,7 @@ func SyncerSetUidStatuses() []SyncerSetUidStatus {
 // is generally not useful.
 type MetricsEngine interface {
 	RecordConnectionAccept(success bool)
+	RecordTMaxTimeout()
 	RecordConnectionClose(success bool)
 	RecordRequest(labels Labels)                           // ignores adapter. only statusOk and statusErr fom status
 	RecordImps(labels ImpLabels)                           // RecordImps across openRTB2 engines that support the 'Native' Imp Type

metrics/metrics_mock.go

@@ -22,6 +22,11 @@ func (me *MetricsEngineMock) RecordConnectionAccept(success bool) {
 	me.Called(success)
 }
 
+// RecordTMaxTimeout mock
+func (me *MetricsEngineMock) RecordTMaxTimeout() {
+	me.Called()
+}
+
 // RecordConnectionClose mock
 func (me *MetricsEngineMock) RecordConnectionClose(success bool) {
 	me.Called(success)

metrics/prometheus/prometheus.go

@@ -18,6 +18,7 @@ type Metrics struct {
 	Gatherer   *prometheus.Registry
 
 	// General Metrics
+	tmaxTimeout                  prometheus.Counter
 	connectionsClosed            prometheus.Counter
 	connectionsError             *prometheus.CounterVec
 	connectionsOpened            prometheus.Counter
@@ -197,6 +198,10 @@ func NewMetrics(cfg config.PrometheusMetrics, disabledMetrics config.DisabledMet
 		"connections_opened",
 		"Count of successful connections opened to Prebid Server.")
 
+	metrics.tmaxTimeout = newCounterWithoutLabels(cfg, reg,
+		"tmax_timeout",
+		"Count of requests rejected due to Tmax timeout exceed.")
+
 	metrics.cookieSync = newCounter(cfg, reg,
 		"cookie_sync_requests",
 		"Count of cookie sync requests to Prebid Server.",
@@ -685,6 +690,10 @@ func (m *Metrics) RecordConnectionAccept(success bool) {
 	}
 }
 
+func (m *Metrics) RecordTMaxTimeout() {
+	m.tmaxTimeout.Inc()
+}
+
 func (m *Metrics) RecordConnectionClose(success bool) {
 	if success {
 		m.connectionsClosed.Inc()