Debug Metrics Implementation (prebid#2246)

config/config.go

@@ -487,6 +487,9 @@ type DisabledMetrics struct {
 	// True if we want to stop collecting account-to-adapter metrics
 	AccountAdapterDetails bool `mapstructure:"account_adapter_details"`
 
+	// True if we want to stop collecting account debug request metrics
+	AccountDebug bool `mapstructure:"account_debug"`
+
 	// True if we don't want to collect metrics about the connections prebid
 	// server establishes with bidder servers such as the number of connections
 	// that were created or reused.
@@ -780,6 +783,7 @@ func SetupViper(v *viper.Viper, filename string) {
 	v.SetDefault("http_client_cache.idle_connection_timeout_seconds", 60)
 	// no metrics configured by default (metrics{host|database|username|password})
 	v.SetDefault("metrics.disabled_metrics.account_adapter_details", false)
+	v.SetDefault("metrics.disabled_metrics.account_debug", true)
 	v.SetDefault("metrics.disabled_metrics.adapter_connections_metrics", true)
 	v.SetDefault("metrics.disabled_metrics.adapter_gdpr_request_blocked", false)
 	v.SetDefault("metrics.influxdb.host", "")

config/config_test.go

@@ -137,6 +137,7 @@ func TestDefaults(t *testing.T) {
 	cmpBools(t, "account_required", cfg.AccountRequired, false)
 	cmpInts(t, "metrics.influxdb.collection_rate_seconds", cfg.Metrics.Influxdb.MetricSendInterval, 20)
 	cmpBools(t, "account_adapter_details", cfg.Metrics.Disabled.AccountAdapterDetails, false)
+	cmpBools(t, "account_debug", cfg.Metrics.Disabled.AccountDebug, true)
 	cmpBools(t, "adapter_connections_metrics", cfg.Metrics.Disabled.AdapterConnectionMetrics, true)
 	cmpBools(t, "adapter_gdpr_request_blocked", cfg.Metrics.Disabled.AdapterGDPRRequestBlocked, false)
 	cmpStrings(t, "certificates_file", cfg.PemCertsFile, "")
@@ -339,6 +340,7 @@ metrics:
     metric_send_interval: 30
   disabled_metrics:
     account_adapter_details: true
+    account_debug: false
     adapter_connections_metrics: true
     adapter_gdpr_request_blocked: true
 adapters:
@@ -611,6 +613,7 @@ func TestFullConfig(t *testing.T) {
 	cmpBools(t, "account_required", cfg.AccountRequired, true)
 	cmpBools(t, "auto_gen_source_tid", cfg.AutoGenSourceTID, false)
 	cmpBools(t, "account_adapter_details", cfg.Metrics.Disabled.AccountAdapterDetails, true)
+	cmpBools(t, "account_debug", cfg.Metrics.Disabled.AccountDebug, false)
 	cmpBools(t, "adapter_connections_metrics", cfg.Metrics.Disabled.AdapterConnectionMetrics, true)
 	cmpBools(t, "adapter_gdpr_request_blocked", cfg.Metrics.Disabled.AdapterGDPRRequestBlocked, true)
 	cmpStrings(t, "certificates_file", cfg.PemCertsFile, "/etc/ssl/cert.pem")

endpoints/openrtb2/amp_auction.go

@@ -206,6 +206,7 @@ func (deps *endpointDeps) AmpAuction(w http.ResponseWriter, r *http.Request, _ h
 		GDPRPermissionsBuilder:     aggregatedGDPR.NewPermissions,
 		StoredAuctionResponses:     storedAuctionResponses,
 		StoredBidResponses:         storedBidResponses,
+		PubID:                      labels.PubID,
 	}
 
 	response, err := deps.ex.HoldAuction(ctx, auctionRequest, nil)

endpoints/openrtb2/auction.go

@@ -5,7 +5,6 @@ import (
 	"encoding/json"
 	"errors"
 	"fmt"
-	"github.com/prebid/prebid-server/gdpr"
 	"io"
 	"io/ioutil"
 	"net/http"
@@ -14,6 +13,8 @@ import (
 	"strconv"
 	"time"
 
+	"github.com/prebid/prebid-server/gdpr"
+
 	"github.com/buger/jsonparser"
 	"github.com/gofrs/uuid"
 	"github.com/golang/glog"
@@ -214,8 +215,8 @@ func (deps *endpointDeps) Auction(w http.ResponseWriter, r *http.Request, _ http
 		StoredBidResponses:         storedBidResponses,
 		TCF2ConfigBuilder:          gdpr.NewTCF2Config,
 		GDPRPermissionsBuilder:     gdpr.NewPermissions,
+		PubID:                      labels.PubID,
 	}
-
 	response, err := deps.ex.HoldAuction(ctx, auctionRequest, nil)
 	ao.Request = req.BidRequest
 	ao.Response = response

endpoints/openrtb2/video_auction.go

@@ -297,6 +297,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re
 		TCF2ConfigBuilder:          gdpr.NewTCF2Config,
 		GDPRPermissionsBuilder:     gdpr.NewPermissions,
 		GlobalPrivacyControlHeader: secGPC,
+		PubID:                      labels.PubID,
 	}
 
 	response, err := deps.ex.HoldAuction(ctx, auctionRequest, &debugLog)

exchange/exchange.go

@@ -172,6 +172,7 @@ type AuctionRequest struct {
 	GDPRPermissionsBuilder gdpr.PermissionsBuilder
 	// map of imp id to bidder to stored response
 	StoredBidResponses stored_responses.ImpBidderStoredResp
+	PubID              string
 }
 
 // BidderRequest holds the bidder specific request and all other
@@ -209,6 +210,7 @@ func (e *exchange) HoldAuction(ctx context.Context, r AuctionRequest, debugLog *
 		}
 		r.ResolvedBidRequest = resolvedBidReq
 	}
+	e.me.RecordDebugRequest(responseDebugAllow || accountDebugAllow, r.PubID)
 
 	if r.RequestType == metrics.ReqTypeORTB2Web || r.RequestType == metrics.ReqTypeORTB2App {
 		//Extract First party data for auction endpoint only

exchange/exchange_test.go

@@ -3752,7 +3752,6 @@ func TestStoredAuctionResponses(t *testing.T) {
 			GDPRPermissionsBuilder: mockGDPRPermissionsBuilder,
 			TCF2ConfigBuilder:      mockTCF2ConfigBuilder,
 		}
-
 		// Run test
 		outBidResponse, err := e.HoldAuction(context.Background(), auctionRequest, &DebugLog{})
 		if test.errorExpected {

exchange/utils.go

@@ -4,9 +4,10 @@ import (
 	"context"
 	"encoding/json"
 	"fmt"
-	"github.com/prebid/prebid-server/stored_responses"
 	"math/rand"
 
+	"github.com/prebid/prebid-server/stored_responses"
+
 	"github.com/buger/jsonparser"
 	"github.com/mxmCherry/openrtb/v15/openrtb2"
 	"github.com/prebid/go-gdpr/vendorconsent"

metrics/config/metrics.go

@@ -254,6 +254,13 @@ func (me *MultiMetricsEngine) RecordAdapterGDPRRequestBlocked(adapter openrtb_ex
 	}
 }
 
+// RecordDebugRequest across all engines
+func (me *MultiMetricsEngine) RecordDebugRequest(debugEnabled bool, pubId string) {
+	for _, thisME := range *me {
+		thisME.RecordDebugRequest(debugEnabled, pubId)
+	}
+}
+
 // NilMetricsEngine implements the MetricsEngine interface where no metrics are actually captured. This is
 // used if no metric backend is configured and also for tests.
 type NilMetricsEngine struct{}
@@ -365,3 +372,7 @@ func (me *NilMetricsEngine) RecordRequestPrivacy(privacy metrics.PrivacyLabels)
 // RecordAdapterGDPRRequestBlocked as a noop
 func (me *NilMetricsEngine) RecordAdapterGDPRRequestBlocked(adapter openrtb_ext.BidderName) {
 }
+
+// RecordDebugRequest as a noop
+func (me *NilMetricsEngine) RecordDebugRequest(debugEnabled bool, pubId string) {
+}

metrics/go_metrics.go

@@ -20,6 +20,7 @@ type Metrics struct {
 	ImpMeter                       metrics.Meter
 	AppRequestMeter                metrics.Meter
 	NoCookieMeter                  metrics.Meter
+	DebugRequestMeter              metrics.Meter
 	RequestTimer                   metrics.Timer
 	RequestsQueueTimer             map[RequestType]map[bool]metrics.Timer
 	PrebidCacheRequestTimerSuccess metrics.Timer
@@ -94,6 +95,7 @@ type MarkupDeliveryMetrics struct {
 
 type accountMetrics struct {
 	requestMeter      metrics.Meter
+	debugRequestMeter metrics.Meter
 	bidsReceivedMeter metrics.Meter
 	priceHistogram    metrics.Histogram
 	// store account by adapter metrics. Type is map[PBSBidder.BidderCode]
@@ -119,6 +121,7 @@ func NewBlankMetrics(registry metrics.Registry, exchanges []openrtb_ext.BidderNa
 		ConnectionCloseErrorMeter:      blankMeter,
 		ImpMeter:                       blankMeter,
 		AppRequestMeter:                blankMeter,
+		DebugRequestMeter:              blankMeter,
 		NoCookieMeter:                  blankMeter,
 		RequestTimer:                   blankTimer,
 		DNSLookupTimer:                 blankTimer,
@@ -219,6 +222,7 @@ func NewMetrics(registry metrics.Registry, exchanges []openrtb_ext.BidderName, d
 
 	newMetrics.NoCookieMeter = metrics.GetOrRegisterMeter("no_cookie_requests", registry)
 	newMetrics.AppRequestMeter = metrics.GetOrRegisterMeter("app_requests", registry)
+	newMetrics.DebugRequestMeter = metrics.GetOrRegisterMeter("debug_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)
@@ -394,6 +398,7 @@ func (me *Metrics) getAccountMetrics(id string) *accountMetrics {
 	}
 	am = &accountMetrics{}
 	am.requestMeter = metrics.GetOrRegisterMeter(fmt.Sprintf("account.%s.requests", id), me.MetricsRegistry)
+	am.debugRequestMeter = metrics.GetOrRegisterMeter(fmt.Sprintf("account.%s.debug_requests", id), me.MetricsRegistry)
 	am.bidsReceivedMeter = metrics.GetOrRegisterMeter(fmt.Sprintf("account.%s.bids_received", id), me.MetricsRegistry)
 	am.priceHistogram = metrics.GetOrRegisterHistogram(fmt.Sprintf("account.%s.prices", id), me.MetricsRegistry, metrics.NewExpDecaySample(1028, 0.015))
 	am.adapterMetrics = make(map[openrtb_ext.BidderName]*AdapterMetrics, len(me.exchanges))
@@ -430,6 +435,18 @@ func (me *Metrics) RecordRequest(labels Labels) {
 	am.requestMeter.Mark(1)
 }
 
+func (me *Metrics) RecordDebugRequest(debugEnabled bool, pubID string) {
+	if debugEnabled {
+		me.DebugRequestMeter.Mark(1)
+		if pubID != PublisherUnknown {
+			am := me.getAccountMetrics(pubID)
+			if !me.MetricsDisabled.AccountDebug {
+				am.debugRequestMeter.Mark(1)
+			}
+		}
+	}
+}
+
 func (me *Metrics) RecordImps(labels ImpLabels) {
 	me.ImpMeter.Mark(int64(1))
 	if labels.BannerImps {

metrics/go_metrics_test.go

@@ -16,6 +16,7 @@ func TestNewMetrics(t *testing.T) {
 	m := NewMetrics(registry, []openrtb_ext.BidderName{openrtb_ext.BidderAppnexus, openrtb_ext.BidderRubicon}, config.DisabledMetrics{}, syncerKeys)
 
 	ensureContains(t, registry, "app_requests", m.AppRequestMeter)
+	ensureContains(t, registry, "debug_requests", m.DebugRequestMeter)
 	ensureContains(t, registry, "no_cookie_requests", m.NoCookieMeter)
 	ensureContains(t, registry, "request_time", m.RequestTimer)
 	ensureContains(t, registry, "amp_no_cookie_requests", m.AmpNoCookieMeter)
@@ -181,6 +182,72 @@ func TestRecordBidTypeDisabledConfig(t *testing.T) {
 	}
 }
 
+func TestRecordDebugRequest(t *testing.T) {
+	testCases := []struct {
+		description               string
+		givenDisabledMetrics      config.DisabledMetrics
+		givenDebugEnabledFlag     bool
+		givenPubID                string
+		expectedAccountDebugCount int64
+		expectedDebugCount        int64
+	}{
+		{
+			description: "Debug is enabled and account debug is enabled, both metrics should be updated",
+			givenDisabledMetrics: config.DisabledMetrics{
+				AccountAdapterDetails: true,
+				AccountDebug:          false,
+			},
+			givenDebugEnabledFlag:     true,
+			givenPubID:                "acct-id",
+			expectedAccountDebugCount: 1,
+			expectedDebugCount:        1,
+		},
+		{
+			description: "Debug and account debug are disabled, niether metrics should be updated",
+			givenDisabledMetrics: config.DisabledMetrics{
+				AccountAdapterDetails: true,
+				AccountDebug:          true,
+			},
+			givenDebugEnabledFlag:     false,
+			givenPubID:                "acct-id",
+			expectedAccountDebugCount: 0,
+			expectedDebugCount:        0,
+		},
+		{
+			description: "Debug is enabled and account debug is enabled, but unknown PubID leads to account debug being 0",
+			givenDisabledMetrics: config.DisabledMetrics{
+				AccountAdapterDetails: true,
+				AccountDebug:          false,
+			},
+			givenDebugEnabledFlag:     true,
+			givenPubID:                PublisherUnknown,
+			expectedAccountDebugCount: 0,
+			expectedDebugCount:        1,
+		},
+		{
+			description: "Debug is disabled, account debug is enabled, niether metric should update",
+			givenDisabledMetrics: config.DisabledMetrics{
+				AccountAdapterDetails: true,
+				AccountDebug:          false,
+			},
+			givenDebugEnabledFlag:     false,
+			givenPubID:                "acct-id",
+			expectedAccountDebugCount: 0,
+			expectedDebugCount:        0,
+		},
+	}
+	for _, test := range testCases {
+		registry := metrics.NewRegistry()
+		m := NewMetrics(registry, []openrtb_ext.BidderName{openrtb_ext.BidderAppnexus}, test.givenDisabledMetrics, nil)
+
+		m.RecordDebugRequest(test.givenDebugEnabledFlag, test.givenPubID)
+		am := m.getAccountMetrics(test.givenPubID)
+
+		assert.Equal(t, test.expectedDebugCount, m.DebugRequestMeter.Count())
+		assert.Equal(t, test.expectedAccountDebugCount, am.debugRequestMeter.Count())
+	}
+}
+
 func TestRecordDNSTime(t *testing.T) {
 	testCases := []struct {
 		description         string

metrics/metrics.go

@@ -409,4 +409,5 @@ type MetricsEngine interface {
 	RecordTimeoutNotice(success bool)
 	RecordRequestPrivacy(privacy PrivacyLabels)
 	RecordAdapterGDPRRequestBlocked(adapterName openrtb_ext.BidderName)
+	RecordDebugRequest(debugEnabled bool, pubId string)
 }

metrics/metrics_mock.go

@@ -145,3 +145,8 @@ func (me *MetricsEngineMock) RecordRequestPrivacy(privacy PrivacyLabels) {
 func (me *MetricsEngineMock) RecordAdapterGDPRRequestBlocked(adapterName openrtb_ext.BidderName) {
 	me.Called(adapterName)
 }
+
+// RecordDebugRequest mock
+func (me *MetricsEngineMock) RecordDebugRequest(debugEnabled bool, pubId string) {
+	me.Called(debugEnabled, pubId)
+}

metrics/prometheus/prometheus.go

@@ -27,6 +27,7 @@ type Metrics struct {
 	impressionsLegacy            prometheus.Counter
 	prebidCacheWriteTimer        *prometheus.HistogramVec
 	requests                     *prometheus.CounterVec
+	debugRequests                prometheus.Counter
 	requestsTimer                *prometheus.HistogramVec
 	requestsQueueTimer           *prometheus.HistogramVec
 	requestsWithoutCookie        *prometheus.CounterVec
@@ -68,7 +69,8 @@ type Metrics struct {
 	syncerSets     *prometheus.CounterVec
 
 	// Account Metrics
-	accountRequests *prometheus.CounterVec
+	accountRequests      *prometheus.CounterVec
+	accountDebugRequests *prometheus.CounterVec
 
 	metricsDisabled config.DisabledMetrics
 }
@@ -182,6 +184,10 @@ func NewMetrics(cfg config.PrometheusMetrics, disabledMetrics config.DisabledMet
 		"Count of total requests to Prebid Server labeled by type and status.",
 		[]string{requestTypeLabel, requestStatusLabel})
 
+	metrics.debugRequests = newCounterWithoutLabels(cfg, reg,
+		"debug_requests",
+		"Count of total requests to Prebid Server that have debug enabled")
+
 	metrics.requestsTimer = newHistogramVec(cfg, reg,
 		"request_time_seconds",
 		"Seconds to resolve successful Prebid Server requests labeled by type.",
@@ -370,6 +376,11 @@ func NewMetrics(cfg config.PrometheusMetrics, disabledMetrics config.DisabledMet
 		"Count of total requests to Prebid Server labeled by account.",
 		[]string{accountLabel})
 
+	metrics.accountDebugRequests = newCounter(cfg, reg,
+		"account_debug_requests",
+		"Count of total requests to Prebid Server that have debug enabled labled by account",
+		[]string{accountLabel})
+
 	metrics.requestsQueueTimer = newHistogramVec(cfg, reg,
 		"request_queue_time",
 		"Seconds request was waiting in queue",
@@ -477,6 +488,17 @@ func (m *Metrics) RecordRequest(labels metrics.Labels) {
 	}
 }
 
+func (m *Metrics) RecordDebugRequest(debugEnabled bool, pubID string) {
+	if debugEnabled {
+		m.debugRequests.Inc()
+		if !m.metricsDisabled.AccountDebug && pubID != metrics.PublisherUnknown {
+			m.accountDebugRequests.With(prometheus.Labels{
+				accountLabel: pubID,
+			}).Inc()
+		}
+	}
+}
+
 func (m *Metrics) RecordImps(labels metrics.ImpLabels) {
 	m.impressions.With(prometheus.Labels{
 		isBannerLabel: strconv.FormatBool(labels.BannerImps),