From 77f0302987fb142adb6534948da4987b8d4209b9 Mon Sep 17 00:00:00 2001 From: Hans Hjort Date: Wed, 27 May 2020 16:41:17 -0400 Subject: [PATCH 1/8] Config setup --- config/config.go | 30 ++++++++++++++++++++++++++++++ 1 file changed, 30 insertions(+) diff --git a/config/config.go b/config/config.go index 703606b2824..6fd7fc68214 100755 --- a/config/config.go +++ b/config/config.go @@ -66,6 +66,8 @@ type Configuration struct { PemCertsFile string `mapstructure:"certificates_file"` // Custom headers to handle request timeouts from queueing infrastructure RequestTimeoutHeaders RequestTimeoutHeaders `mapstructure:"request_timeout_headers"` + // Debug/logging flags go here + Debug Debug `mapstructure:"debug"` } const MIN_COOKIE_SIZE_BYTES = 500 @@ -428,6 +430,30 @@ type DefReqFiles struct { FileName string `mapstructure:"name"` } +type Debug struct { + TimeoutNotification TimeoutNotification `mapstructure:"timeout_notification"` +} + +func (cfg *Debug) validate(errs configErrors) configErrors { + return cfg.TimeoutNotification.validate(errs) +} + +type TimeoutNotification struct { + // Log timeout notifications in the application log + Log bool `mapstructure:"log"` + // Fraction of notifications to log + Sampling float32 `mapstructure:"sampling"` + // Only log failures + FailOnly bool `mapstructure:"fail_only"` +} + +func (cfg *TimeoutNotification) validate(errs configErrors) configErrors { + if cfg.Sampling < 0.0 || cfg.Sampling > 1.0 { + errs = append(errs, fmt.Errorf("debug.timeout_notification.sampling must be positive and not greater than 1.0. Got %f", cfg.Sampling)) + } + return errs +} + // New uses viper to get our server configurations. func New(v *viper.Viper) (*Configuration, error) { var c Configuration @@ -785,6 +811,10 @@ func SetupViper(v *viper.Viper, filename string) { v.SetDefault("request_timeout_headers.request_time_in_queue", "") v.SetDefault("request_timeout_headers.request_timeout_in_queue", "") + v.SetDefault("debug.timeout_notification.log", false) + v.SetDefault("debug.timeout_notification.sampling", 0.0) + v.SetDefault("debug.timeout_notification.fail_only", false) + // Set environment variable support: v.SetEnvKeyReplacer(strings.NewReplacer(".", "_")) v.SetEnvPrefix("PBS") From 0c9000768c019b13bb2e848b64f9aefa273214e5 Mon Sep 17 00:00:00 2001 From: Hans Hjort Date: Fri, 29 May 2020 13:48:58 -0400 Subject: [PATCH 2/8] Timeout notification tracking/debugging --- config/util/loggers.go | 18 +++++++++++ config/util/loggers_test.go | 31 +++++++++++++++++++ exchange/adapter_map.go | 6 ++-- exchange/adapter_map_test.go | 5 +-- exchange/bidder.go | 39 +++++++++++++++++++----- exchange/bidder_test.go | 18 ++++++----- exchange/exchange.go | 2 +- exchange/targeting_test.go | 4 ++- pbsmetrics/config/metrics.go | 11 +++++++ pbsmetrics/go_metrics.go | 5 +++ pbsmetrics/metrics.go | 1 + pbsmetrics/metrics_mock.go | 5 +++ pbsmetrics/prometheus/prometheus.go | 23 ++++++++++++++ pbsmetrics/prometheus/prometheus_test.go | 21 +++++++++++++ 14 files changed, 168 insertions(+), 21 deletions(-) create mode 100644 config/util/loggers.go create mode 100644 config/util/loggers_test.go diff --git a/config/util/loggers.go b/config/util/loggers.go new file mode 100644 index 00000000000..2e6b4df6c88 --- /dev/null +++ b/config/util/loggers.go @@ -0,0 +1,18 @@ +package util + +import ( + "math/rand" +) + +type logMsg func(string, ...interface{}) + +// LogRandomSample will log a randam sample of the messages it is sent, based on the chance to log +// chance = 1.0 => always log, +// chance = 0.0 => never log +func LogRandomSample(msg string, logger logMsg, chance float32) { + if chance < 1.0 && rand.Float32() > chance { + // this is the chance we don't log anything + return + } + logger(msg) +} diff --git a/config/util/loggers_test.go b/config/util/loggers_test.go new file mode 100644 index 00000000000..84886c7bb8f --- /dev/null +++ b/config/util/loggers_test.go @@ -0,0 +1,31 @@ +package util + +import ( + "bytes" + "fmt" + "math/rand" + "testing" + + "github.com/stretchr/testify/assert" +) + +var expected string = `This is test line 2 +This is test line 3 +` + +func TestLogRandomSample(t *testing.T) { + rand.Seed(1337) + var buf bytes.Buffer + + mylogger := func(msg string, args ...interface{}) { + buf.WriteString(fmt.Sprintf(fmt.Sprintln(msg), args...)) + } + + LogRandomSample("This is test line 1", mylogger, 0.5) + LogRandomSample("This is test line 2", mylogger, 0.5) + LogRandomSample("This is test line 3", mylogger, 0.5) + LogRandomSample("This is test line 4", mylogger, 0.5) + LogRandomSample("This is test line 5", mylogger, 0.5) + + assert.EqualValues(t, expected, buf.String()) +} diff --git a/exchange/adapter_map.go b/exchange/adapter_map.go index 15e57f55105..8c2a63d500f 100755 --- a/exchange/adapter_map.go +++ b/exchange/adapter_map.go @@ -5,6 +5,8 @@ import ( "net/http" "strings" + "github.com/prebid/prebid-server/pbsmetrics" + "github.com/prebid/prebid-server/adapters" ttx "github.com/prebid/prebid-server/adapters/33across" "github.com/prebid/prebid-server/adapters/adform" @@ -82,7 +84,7 @@ import ( // The newAdapterMap function is segregated to its own file to make it a simple and clean location for each Adapter // to register itself. No wading through Exchange code to find it. -func newAdapterMap(client *http.Client, cfg *config.Configuration, infos adapters.BidderInfos) map[openrtb_ext.BidderName]adaptedBidder { +func newAdapterMap(client *http.Client, cfg *config.Configuration, infos adapters.BidderInfos, me pbsmetrics.MetricsEngine) map[openrtb_ext.BidderName]adaptedBidder { ortbBidders := map[openrtb_ext.BidderName]adapters.Bidder{ openrtb_ext.Bidder33Across: ttx.New33AcrossBidder(cfg.Adapters[string(openrtb_ext.Bidder33Across)].Endpoint), openrtb_ext.BidderAdform: adform.NewAdformBidder(client, cfg.Adapters[string(openrtb_ext.BidderAdform)].Endpoint), @@ -184,7 +186,7 @@ func newAdapterMap(client *http.Client, cfg *config.Configuration, infos adapter for name, bidder := range ortbBidders { // Clean out any disabled bidders if infos[string(name)].Status == adapters.StatusActive { - allBidders[name] = adaptBidder(adapters.EnforceBidderInfo(bidder, infos[string(name)]), client) + allBidders[name] = adaptBidder(adapters.EnforceBidderInfo(bidder, infos[string(name)]), client, cfg, me) } } diff --git a/exchange/adapter_map_test.go b/exchange/adapter_map_test.go index a732f357897..f472ab1d988 100644 --- a/exchange/adapter_map_test.go +++ b/exchange/adapter_map_test.go @@ -7,11 +7,12 @@ import ( "github.com/prebid/prebid-server/adapters" "github.com/prebid/prebid-server/config" "github.com/prebid/prebid-server/openrtb_ext" + metricsConfig "github.com/prebid/prebid-server/pbsmetrics/config" ) func TestNewAdapterMap(t *testing.T) { cfg := &config.Configuration{Adapters: blankAdapterConfig(openrtb_ext.BidderList())} - adapterMap := newAdapterMap(nil, cfg, adapters.ParseBidderInfos(cfg.Adapters, "../static/bidder-info", openrtb_ext.BidderList())) + adapterMap := newAdapterMap(nil, cfg, adapters.ParseBidderInfos(cfg.Adapters, "../static/bidder-info", openrtb_ext.BidderList()), &metricsConfig.DummyMetricsEngine{}) for _, bidderName := range openrtb_ext.BidderMap { if bidder, ok := adapterMap[bidderName]; bidder == nil || !ok { t.Errorf("adapterMap missing expected Bidder: %s", string(bidderName)) @@ -38,7 +39,7 @@ func TestNewAdapterMapDisabledAdapters(t *testing.T) { } } } - adapterMap := newAdapterMap(nil, &config.Configuration{Adapters: cfgAdapters}, adapters.ParseBidderInfos(cfgAdapters, "../static/bidder-info", bidderList)) + adapterMap := newAdapterMap(nil, &config.Configuration{Adapters: cfgAdapters}, adapters.ParseBidderInfos(cfgAdapters, "../static/bidder-info", bidderList), &metricsConfig.DummyMetricsEngine{}) for _, bidderName := range openrtb_ext.BidderMap { if bidder, ok := adapterMap[bidderName]; bidder == nil || !ok { if inList(bidderList, bidderName) { diff --git a/exchange/bidder.go b/exchange/bidder.go index 7a53db5ee97..9ddc2378627 100644 --- a/exchange/bidder.go +++ b/exchange/bidder.go @@ -10,13 +10,18 @@ import ( "net/http" "time" + "github.com/golang/glog" + "github.com/prebid/prebid-server/config/util" + "github.com/mxmCherry/openrtb" nativeRequests "github.com/mxmCherry/openrtb/native/request" nativeResponse "github.com/mxmCherry/openrtb/native/response" "github.com/prebid/prebid-server/adapters" + "github.com/prebid/prebid-server/config" "github.com/prebid/prebid-server/currencies" "github.com/prebid/prebid-server/errortypes" "github.com/prebid/prebid-server/openrtb_ext" + "github.com/prebid/prebid-server/pbsmetrics" "golang.org/x/net/context/ctxhttp" ) @@ -82,16 +87,20 @@ type pbsOrtbSeatBid struct { // // The name refers to the "Adapter" architecture pattern, and should not be confused with a Prebid "Adapter" // (which is being phased out and replaced by Bidder for OpenRTB auctions) -func adaptBidder(bidder adapters.Bidder, client *http.Client) adaptedBidder { +func adaptBidder(bidder adapters.Bidder, client *http.Client, cfg *config.Configuration, me pbsmetrics.MetricsEngine) adaptedBidder { return &bidderAdapter{ - Bidder: bidder, - Client: client, + Bidder: bidder, + Client: client, + DebugCfg: cfg.Debug, + me: me, } } type bidderAdapter struct { - Bidder adapters.Bidder - Client *http.Client + Bidder adapters.Bidder + Client *http.Client + DebugCfg config.Debug + me pbsmetrics.MetricsEngine } func (bidder *bidderAdapter) requestBid(ctx context.Context, request *openrtb.BidRequest, name openrtb_ext.BidderName, bidAdjustment float64, conversions currencies.Conversions, reqInfo *adapters.ExtraRequestInfo) (*pbsOrtbSeatBid, []error) { @@ -365,8 +374,24 @@ func (bidder *bidderAdapter) doTimeoutNotification(timeoutBidder adapters.Timeou httpReq, err := http.NewRequest(toReq.Method, toReq.Uri, bytes.NewBuffer(toReq.Body)) if err == nil { httpReq.Header = req.Headers - ctxhttp.Do(ctx, bidder.Client, httpReq) - // No validation yet on sending notifications + httpResp, err := ctxhttp.Do(ctx, bidder.Client, httpReq) + success := true + if err != nil || httpResp.StatusCode < 200 || httpResp.StatusCode >= 300 { + success = false + } + bidder.me.RecordTimeoutNotice(success) + if bidder.DebugCfg.TimeoutNotification.Log && !(bidder.DebugCfg.TimeoutNotification.FailOnly && success) { + var msg string + if err == nil { + msg = fmt.Sprintf("TimeoutNotification: status:(%d) body:%s", httpResp.StatusCode, string(toReq.Body)) + } else { + msg = fmt.Sprintf("TimeoutNotification: error:(%s) body:%s", err.Error(), string(toReq.Body)) + } + // If logging is turned on, and logging is not disallowed via FailOnly + util.LogRandomSample(msg, glog.Warningf, bidder.DebugCfg.TimeoutNotification.Sampling) + } + } else { + bidder.me.RecordTimeoutNotice(false) } } diff --git a/exchange/bidder_test.go b/exchange/bidder_test.go index f20b431c13a..fa04e6a4771 100644 --- a/exchange/bidder_test.go +++ b/exchange/bidder_test.go @@ -12,8 +12,10 @@ import ( "github.com/mxmCherry/openrtb" "github.com/prebid/prebid-server/adapters" + "github.com/prebid/prebid-server/config" "github.com/prebid/prebid-server/currencies" "github.com/prebid/prebid-server/openrtb_ext" + metricsConfig "github.com/prebid/prebid-server/pbsmetrics/config" "github.com/stretchr/testify/assert" nativeRequests "github.com/mxmCherry/openrtb/native/request" @@ -64,7 +66,7 @@ func TestSingleBidder(t *testing.T) { }, bidResponse: mockBidderResponse, } - bidder := adaptBidder(bidderImpl, server.Client()) + bidder := adaptBidder(bidderImpl, server.Client(), &config.Configuration{}, &metricsConfig.DummyMetricsEngine{}) currencyConverter := currencies.NewRateConverterDefault() seatBid, errs := bidder.requestBid(context.Background(), &openrtb.BidRequest{}, "test", bidAdjustment, currencyConverter.Rates(), &adapters.ExtraRequestInfo{}) @@ -152,7 +154,7 @@ func TestMultiBidder(t *testing.T) { }}, bidResponse: mockBidderResponse, } - bidder := adaptBidder(bidderImpl, server.Client()) + bidder := adaptBidder(bidderImpl, server.Client(), &config.Configuration{}, &metricsConfig.DummyMetricsEngine{}) currencyConverter := currencies.NewRateConverterDefault() seatBid, errs := bidder.requestBid(context.Background(), &openrtb.BidRequest{}, "test", 1.0, currencyConverter.Rates(), &adapters.ExtraRequestInfo{}) @@ -510,7 +512,7 @@ func TestMultiCurrencies(t *testing.T) { ) // Execute: - bidder := adaptBidder(bidderImpl, server.Client()) + bidder := adaptBidder(bidderImpl, server.Client(), &config.Configuration{}, &metricsConfig.DummyMetricsEngine{}) currencyConverter := currencies.NewRateConverter( &http.Client{}, mockedHTTPServer.URL, @@ -658,7 +660,7 @@ func TestMultiCurrencies_RateConverterNotSet(t *testing.T) { } // Execute: - bidder := adaptBidder(bidderImpl, server.Client()) + bidder := adaptBidder(bidderImpl, server.Client(), &config.Configuration{}, &metricsConfig.DummyMetricsEngine{}) currencyConverter := currencies.NewRateConverterDefault() seatBid, errs := bidder.requestBid( context.Background(), @@ -824,7 +826,7 @@ func TestMultiCurrencies_RequestCurrencyPick(t *testing.T) { } // Execute: - bidder := adaptBidder(bidderImpl, server.Client()) + bidder := adaptBidder(bidderImpl, server.Client(), &config.Configuration{}, &metricsConfig.DummyMetricsEngine{}) currencyConverter := currencies.NewRateConverter( &http.Client{}, mockedHTTPServer.URL, @@ -939,7 +941,7 @@ func TestServerCallDebugging(t *testing.T) { Headers: http.Header{}, }, } - bidder := adaptBidder(bidderImpl, server.Client()) + bidder := adaptBidder(bidderImpl, server.Client(), &config.Configuration{}, &metricsConfig.DummyMetricsEngine{}) currencyConverter := currencies.NewRateConverterDefault() bids, _ := bidder.requestBid( @@ -1051,7 +1053,7 @@ func TestMobileNativeTypes(t *testing.T) { }, bidResponse: tc.mockBidderResponse, } - bidder := adaptBidder(bidderImpl, server.Client()) + bidder := adaptBidder(bidderImpl, server.Client(), &config.Configuration{}, &metricsConfig.DummyMetricsEngine{}) currencyConverter := currencies.NewRateConverterDefault() seatBids, _ := bidder.requestBid( @@ -1072,7 +1074,7 @@ func TestMobileNativeTypes(t *testing.T) { } func TestErrorReporting(t *testing.T) { - bidder := adaptBidder(&bidRejector{}, nil) + bidder := adaptBidder(&bidRejector{}, nil, &config.Configuration{}, &metricsConfig.DummyMetricsEngine{}) currencyConverter := currencies.NewRateConverterDefault() bids, errs := bidder.requestBid(context.Background(), &openrtb.BidRequest{}, "test", 1.0, currencyConverter.Rates(), &adapters.ExtraRequestInfo{}) if bids != nil { diff --git a/exchange/exchange.go b/exchange/exchange.go index 6d51b87de4a..660beb641ef 100644 --- a/exchange/exchange.go +++ b/exchange/exchange.go @@ -69,7 +69,7 @@ type bidResponseWrapper struct { func NewExchange(client *http.Client, cache prebid_cache_client.Client, cfg *config.Configuration, metricsEngine pbsmetrics.MetricsEngine, infos adapters.BidderInfos, gDPR gdpr.Permissions, currencyConverter *currencies.RateConverter) Exchange { e := new(exchange) - e.adapterMap = newAdapterMap(client, cfg, infos) + e.adapterMap = newAdapterMap(client, cfg, infos, metricsEngine) e.cache = cache e.cacheTime = time.Duration(cfg.CacheURL.ExpectedTimeMillis) * time.Millisecond e.me = metricsEngine diff --git a/exchange/targeting_test.go b/exchange/targeting_test.go index f86309684c6..72de1d4261f 100644 --- a/exchange/targeting_test.go +++ b/exchange/targeting_test.go @@ -8,12 +8,14 @@ import ( "testing" "time" + "github.com/prebid/prebid-server/config" "github.com/prebid/prebid-server/currencies" "github.com/prebid/prebid-server/gdpr" "github.com/prebid/prebid-server/pbsmetrics" metricsConf "github.com/prebid/prebid-server/pbsmetrics/config" + metricsConfig "github.com/prebid/prebid-server/pbsmetrics/config" "github.com/mxmCherry/openrtb" "github.com/prebid/prebid-server/adapters" @@ -132,7 +134,7 @@ func buildAdapterMap(bids map[openrtb_ext.BidderName][]*openrtb.Bid, mockServerU adapterMap[bidder] = adaptBidder(&mockTargetingBidder{ mockServerURL: mockServerURL, bids: bids, - }, client) + }, client, &config.Configuration{}, &metricsConfig.DummyMetricsEngine{}) } return adapterMap } diff --git a/pbsmetrics/config/metrics.go b/pbsmetrics/config/metrics.go index e1cdaceb0e5..4e249785ba6 100644 --- a/pbsmetrics/config/metrics.go +++ b/pbsmetrics/config/metrics.go @@ -188,6 +188,13 @@ func (me *MultiMetricsEngine) RecordRequestQueueTime(success bool, requestType p } } +// RecordTimeoutNotice across all engines +func (me *MultiMetricsEngine) RecordTimeoutNotice(success bool) { + for _, thisME := range *me { + thisME.RecordTimeoutNotice(success) + } +} + // DummyMetricsEngine is a Noop metrics engine in case no metrics are configured. (may also be useful for tests) type DummyMetricsEngine struct{} @@ -262,3 +269,7 @@ func (me *DummyMetricsEngine) RecordPrebidCacheRequestTime(success bool, length // RecordRequestQueueTime as a noop func (me *DummyMetricsEngine) RecordRequestQueueTime(success bool, requestType pbsmetrics.RequestType, length time.Duration) { } + +// RecordTimeoutNotice as a noop +func (me *DummyMetricsEngine) RecordTimeoutNotice(success bool) { +} diff --git a/pbsmetrics/go_metrics.go b/pbsmetrics/go_metrics.go index ff3d9681fb1..b18a64bba63 100644 --- a/pbsmetrics/go_metrics.go +++ b/pbsmetrics/go_metrics.go @@ -544,6 +544,11 @@ func (me *Metrics) RecordRequestQueueTime(success bool, requestType RequestType, } +func (me *Metrics) RecordTimeoutNotice(sucess bool) { + // Not yet implemented for influx + return +} + func doMark(bidder openrtb_ext.BidderName, meters map[openrtb_ext.BidderName]metrics.Meter) { met, ok := meters[bidder] if ok { diff --git a/pbsmetrics/metrics.go b/pbsmetrics/metrics.go index 611692c9c01..e65ba313338 100644 --- a/pbsmetrics/metrics.go +++ b/pbsmetrics/metrics.go @@ -275,4 +275,5 @@ type MetricsEngine interface { RecordStoredImpCacheResult(cacheResult CacheResult, inc int) RecordPrebidCacheRequestTime(success bool, length time.Duration) RecordRequestQueueTime(success bool, requestType RequestType, length time.Duration) + RecordTimeoutNotice(sucess bool) } diff --git a/pbsmetrics/metrics_mock.go b/pbsmetrics/metrics_mock.go index 1f5b84b1e0f..482cbf24fae 100644 --- a/pbsmetrics/metrics_mock.go +++ b/pbsmetrics/metrics_mock.go @@ -101,3 +101,8 @@ func (me *MetricsEngineMock) RecordPrebidCacheRequestTime(success bool, length t func (me *MetricsEngineMock) RecordRequestQueueTime(success bool, requestType RequestType, length time.Duration) { me.Called(success, requestType, length) } + +// RecordTimeoutNotice mock +func (me *MetricsEngineMock) RecordTimeoutNotice(success bool) { + me.Called(success) +} diff --git a/pbsmetrics/prometheus/prometheus.go b/pbsmetrics/prometheus/prometheus.go index d66defea4cd..e385b044981 100644 --- a/pbsmetrics/prometheus/prometheus.go +++ b/pbsmetrics/prometheus/prometheus.go @@ -28,6 +28,7 @@ type Metrics struct { requestsWithoutCookie *prometheus.CounterVec storedImpressionsCacheResult *prometheus.CounterVec storedRequestCacheResult *prometheus.CounterVec + timeout_notifications *prometheus.CounterVec // Adapter Metrics adapterBids *prometheus.CounterVec @@ -79,6 +80,11 @@ const ( requestRejectLabel = "requestRejectedLabel" ) +const ( + requestSuccessful = "ok" + requestFailed = "failed" +) + // NewMetrics initializes a new Prometheus metrics instance with preloaded label values. func NewMetrics(cfg config.PrometheusMetrics) *Metrics { requestTimeBuckets := []float64{0.05, 0.1, 0.15, 0.20, 0.25, 0.3, 0.4, 0.5, 0.75, 1} @@ -147,6 +153,11 @@ func NewMetrics(cfg config.PrometheusMetrics) *Metrics { "Count of stored request cache requests attempts by hits or miss.", []string{cacheResultLabel}) + metrics.timeout_notifications = newCounter(cfg, metrics.Registry, + "timeout_notification", + "Count of timeout notifications triggered, and if they were successfully sent.", + []string{successLabel}) + metrics.adapterBids = newCounter(cfg, metrics.Registry, "adapter_bids", "Count of bids labeled by adapter and markup delivery type (adm or nurl).", @@ -398,3 +409,15 @@ func (m *Metrics) RecordRequestQueueTime(success bool, requestType pbsmetrics.Re requestStatusLabel: successLabelFormatted, }).Observe(length.Seconds()) } + +func (m *Metrics) RecordTimeoutNotice(success bool) { + if success { + m.timeout_notifications.With(prometheus.Labels{ + successLabel: requestSuccessful, + }).Inc() + } else { + m.timeout_notifications.With(prometheus.Labels{ + successLabel: requestFailed, + }).Inc() + } +} diff --git a/pbsmetrics/prometheus/prometheus_test.go b/pbsmetrics/prometheus/prometheus_test.go index e4d6a4f78d1..24c50492139 100644 --- a/pbsmetrics/prometheus/prometheus_test.go +++ b/pbsmetrics/prometheus/prometheus_test.go @@ -923,6 +923,27 @@ func TestRecordRequestQueueTimeMetric(t *testing.T) { } } +func TestTimeoutNotifications(t *testing.T) { + m := createMetricsForTesting() + + m.RecordTimeoutNotice(true) + m.RecordTimeoutNotice(true) + m.RecordTimeoutNotice(false) + + assertCounterVecValue(t, "", "timeout_notifications:ok", m.timeout_notifications, + float64(2), + prometheus.Labels{ + successLabel: requestSuccessful, + }) + + assertCounterVecValue(t, "", "timeout_notifications:fail", m.timeout_notifications, + float64(1), + prometheus.Labels{ + successLabel: requestFailed, + }) + +} + func assertCounterValue(t *testing.T, description, name string, counter prometheus.Counter, expected float64) { m := dto.Metric{} counter.Write(&m) From 811d8856011965dc67f68f0268c8254f4a978d86 Mon Sep 17 00:00:00 2001 From: Hans Hjort Date: Tue, 2 Jun 2020 14:30:22 -0400 Subject: [PATCH 3/8] Adds some documentation on timeout notifications --- docs/developers/add-new-bidder.md | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/docs/developers/add-new-bidder.md b/docs/developers/add-new-bidder.md index e68185fdd1c..d76a1fd2fbf 100644 --- a/docs/developers/add-new-bidder.md +++ b/docs/developers/add-new-bidder.md @@ -46,6 +46,16 @@ If bidder is going to support long form video make sure bidder has: Note: `bid.bidVideo.PrimaryCategory` or `TypedBid.bid.Cat` should be specified. To learn more about IAB categories, please refer to this convenience link (not the final official definition): [IAB categories](https://adtagmacros.com/list-of-iab-categories-for-advertisement/) +### Timeout notification support +This is an optional feature. If you wish to get timeout notifications when a bid request from PBS times out, you can implement the +`MakeTimeoutNotification` method in your adapter. If you do not wish timeout notification, do not implement the method. + +`func (a *Adapter) MakeTimeoutNotification(req *adapters.RequestData) (*adapters.RequestData, []error)` + +Here the `RequestData` supplied as an argument is the request returned from `MakeRequests` that timed out. If an adapter generates +multiple requests, and more than one of them times out, then there will be a call to `MakeTimeoutNotification` for each failed +request. The function should then return a `RequestData` object that will be the timeout notification to be sent to the bidder, or a list of errors encountered trying to create the timeout notification request. Timeout notifications will not generate subsequent timeout notifications if they timeout or fail. + ## Test Your Bidder ### Automated Tests From 28a9990f789af99ea29df15806a4fa373ff591c5 Mon Sep 17 00:00:00 2001 From: Hans Hjort Date: Mon, 8 Jun 2020 11:10:32 -0400 Subject: [PATCH 4/8] Better testing --- config/util/loggers.go | 8 +++++++- config/util/loggers_test.go | 12 ++++++------ exchange/bidder.go | 5 +---- 3 files changed, 14 insertions(+), 11 deletions(-) diff --git a/config/util/loggers.go b/config/util/loggers.go index 2e6b4df6c88..88702e68763 100644 --- a/config/util/loggers.go +++ b/config/util/loggers.go @@ -6,11 +6,17 @@ import ( type logMsg func(string, ...interface{}) +type randomGenerator func() float32 + // LogRandomSample will log a randam sample of the messages it is sent, based on the chance to log // chance = 1.0 => always log, // chance = 0.0 => never log func LogRandomSample(msg string, logger logMsg, chance float32) { - if chance < 1.0 && rand.Float32() > chance { + logRandomSampleImpl(msg, logger, chance, rand.Float32) +} + +func logRandomSampleImpl(msg string, logger logMsg, chance float32, randGenerator randomGenerator) { + if chance < 1.0 && randGenerator() > chance { // this is the chance we don't log anything return } diff --git a/config/util/loggers_test.go b/config/util/loggers_test.go index 84886c7bb8f..3a61d1a9910 100644 --- a/config/util/loggers_test.go +++ b/config/util/loggers_test.go @@ -14,18 +14,18 @@ This is test line 3 ` func TestLogRandomSample(t *testing.T) { - rand.Seed(1337) + myRand := rand.New(rand.NewSource(1337)) var buf bytes.Buffer mylogger := func(msg string, args ...interface{}) { buf.WriteString(fmt.Sprintf(fmt.Sprintln(msg), args...)) } - LogRandomSample("This is test line 1", mylogger, 0.5) - LogRandomSample("This is test line 2", mylogger, 0.5) - LogRandomSample("This is test line 3", mylogger, 0.5) - LogRandomSample("This is test line 4", mylogger, 0.5) - LogRandomSample("This is test line 5", mylogger, 0.5) + logRandomSampleImpl("This is test line 1", mylogger, 0.5, myRand.Float32) + logRandomSampleImpl("This is test line 2", mylogger, 0.5, myRand.Float32) + logRandomSampleImpl("This is test line 3", mylogger, 0.5, myRand.Float32) + logRandomSampleImpl("This is test line 4", mylogger, 0.5, myRand.Float32) + logRandomSampleImpl("This is test line 5", mylogger, 0.5, myRand.Float32) assert.EqualValues(t, expected, buf.String()) } diff --git a/exchange/bidder.go b/exchange/bidder.go index 9ddc2378627..85453dc6876 100644 --- a/exchange/bidder.go +++ b/exchange/bidder.go @@ -375,10 +375,7 @@ func (bidder *bidderAdapter) doTimeoutNotification(timeoutBidder adapters.Timeou if err == nil { httpReq.Header = req.Headers httpResp, err := ctxhttp.Do(ctx, bidder.Client, httpReq) - success := true - if err != nil || httpResp.StatusCode < 200 || httpResp.StatusCode >= 300 { - success = false - } + success := (err == nil && httpResp.StatusCode >= 200 && httpResp.StatusCode < 300) bidder.me.RecordTimeoutNotice(success) if bidder.DebugCfg.TimeoutNotification.Log && !(bidder.DebugCfg.TimeoutNotification.FailOnly && success) { var msg string From 87f8846f0ebf1ebe9a3b5b0ae1648cd7e0c18e48 Mon Sep 17 00:00:00 2001 From: Hans Hjort Date: Mon, 8 Jun 2020 11:35:43 -0400 Subject: [PATCH 5/8] Influx support --- pbsmetrics/go_metrics.go | 17 +++++++++++++++-- pbsmetrics/go_metrics_test.go | 3 +++ 2 files changed, 18 insertions(+), 2 deletions(-) diff --git a/pbsmetrics/go_metrics.go b/pbsmetrics/go_metrics.go index b18a64bba63..1ced4d57269 100644 --- a/pbsmetrics/go_metrics.go +++ b/pbsmetrics/go_metrics.go @@ -48,6 +48,9 @@ type Metrics struct { ImpsTypeAudio metrics.Meter ImpsTypeNative metrics.Meter + TimeoutNotificationSuccess metrics.Meter + TimeoutNotificationFailure metrics.Meter + AdapterMetrics map[openrtb_ext.BidderName]*AdapterMetrics // Don't export accountMetrics because we need helper functions here to insure its properly populated dynamically accountMetrics map[string]*accountMetrics @@ -131,6 +134,9 @@ func NewBlankMetrics(registry metrics.Registry, exchanges []openrtb_ext.BidderNa ImpsTypeAudio: blankMeter, ImpsTypeNative: blankMeter, + TimeoutNotificationSuccess: blankMeter, + TimeoutNotificationFailure: blankMeter, + AdapterMetrics: make(map[openrtb_ext.BidderName]*AdapterMetrics, len(exchanges)), accountMetrics: make(map[string]*accountMetrics), MetricsDisabled: disableMetrics, @@ -209,6 +215,9 @@ func NewMetrics(registry metrics.Registry, exchanges []openrtb_ext.BidderName, d newMetrics.userSyncSet[unknownBidder] = metrics.GetOrRegisterMeter("usersync.unknown.sets", registry) newMetrics.userSyncGDPRPrevent[unknownBidder] = metrics.GetOrRegisterMeter("usersync.unknown.gdpr_prevent", registry) + + newMetrics.TimeoutNotificationSuccess = metrics.GetOrRegisterMeter("timeout_notification.ok", registry) + newMetrics.TimeoutNotificationFailure = metrics.GetOrRegisterMeter("timeout_notification.failed", registry) return newMetrics } @@ -544,8 +553,12 @@ func (me *Metrics) RecordRequestQueueTime(success bool, requestType RequestType, } -func (me *Metrics) RecordTimeoutNotice(sucess bool) { - // Not yet implemented for influx +func (me *Metrics) RecordTimeoutNotice(success bool) { + if success { + me.TimeoutNotificationSuccess.Mark(1) + } else { + me.TimeoutNotificationFailure.Mark(1) + } return } diff --git a/pbsmetrics/go_metrics_test.go b/pbsmetrics/go_metrics_test.go index 253ff69e3c2..25f75e77758 100644 --- a/pbsmetrics/go_metrics_test.go +++ b/pbsmetrics/go_metrics_test.go @@ -53,6 +53,9 @@ func TestNewMetrics(t *testing.T) { ensureContains(t, registry, "queued_requests.video.rejected", m.RequestsQueueTimer[ReqTypeVideo][false]) ensureContains(t, registry, "queued_requests.video.accepted", m.RequestsQueueTimer[ReqTypeVideo][true]) + + ensureContains(t, registry, "timeout_notification.ok", m.TimeoutNotificationSuccess) + ensureContains(t, registry, "timeout_notification.failed", m.TimeoutNotificationFailure) } func TestRecordBidType(t *testing.T) { From e584ade60739f7dfd09dcb6931067753958ed141 Mon Sep 17 00:00:00 2001 From: Hans Hjort Date: Mon, 8 Jun 2020 16:01:31 -0400 Subject: [PATCH 6/8] PR review fixes --- config/config.go | 8 ++++---- config/util/loggers_test.go | 5 +++-- exchange/bidder.go | 20 ++++++++++---------- 3 files changed, 17 insertions(+), 16 deletions(-) diff --git a/config/config.go b/config/config.go index 6fd7fc68214..5a4dcd9f84b 100755 --- a/config/config.go +++ b/config/config.go @@ -442,14 +442,14 @@ type TimeoutNotification struct { // Log timeout notifications in the application log Log bool `mapstructure:"log"` // Fraction of notifications to log - Sampling float32 `mapstructure:"sampling"` + SamplingRate float32 `mapstructure:"sampling_rate"` // Only log failures FailOnly bool `mapstructure:"fail_only"` } func (cfg *TimeoutNotification) validate(errs configErrors) configErrors { - if cfg.Sampling < 0.0 || cfg.Sampling > 1.0 { - errs = append(errs, fmt.Errorf("debug.timeout_notification.sampling must be positive and not greater than 1.0. Got %f", cfg.Sampling)) + if cfg.SamplingRate < 0.0 || cfg.SamplingRate > 1.0 { + errs = append(errs, fmt.Errorf("debug.timeout_notification.sampling_rate must be positive and not greater than 1.0. Got %f", cfg.SamplingRate)) } return errs } @@ -812,7 +812,7 @@ func SetupViper(v *viper.Viper, filename string) { v.SetDefault("request_timeout_headers.request_timeout_in_queue", "") v.SetDefault("debug.timeout_notification.log", false) - v.SetDefault("debug.timeout_notification.sampling", 0.0) + v.SetDefault("debug.timeout_notification.sampling_rate", 0.0) v.SetDefault("debug.timeout_notification.fail_only", false) // Set environment variable support: diff --git a/config/util/loggers_test.go b/config/util/loggers_test.go index 3a61d1a9910..4bfab967ec4 100644 --- a/config/util/loggers_test.go +++ b/config/util/loggers_test.go @@ -9,11 +9,12 @@ import ( "github.com/stretchr/testify/assert" ) -var expected string = `This is test line 2 +func TestLogRandomSample(t *testing.T) { + + const expected string = `This is test line 2 This is test line 3 ` -func TestLogRandomSample(t *testing.T) { myRand := rand.New(rand.NewSource(1337)) var buf bytes.Buffer diff --git a/exchange/bidder.go b/exchange/bidder.go index 85453dc6876..f9b4a522343 100644 --- a/exchange/bidder.go +++ b/exchange/bidder.go @@ -89,18 +89,18 @@ type pbsOrtbSeatBid struct { // (which is being phased out and replaced by Bidder for OpenRTB auctions) func adaptBidder(bidder adapters.Bidder, client *http.Client, cfg *config.Configuration, me pbsmetrics.MetricsEngine) adaptedBidder { return &bidderAdapter{ - Bidder: bidder, - Client: client, - DebugCfg: cfg.Debug, - me: me, + Bidder: bidder, + Client: client, + DebugConfig: cfg.Debug, + me: me, } } type bidderAdapter struct { - Bidder adapters.Bidder - Client *http.Client - DebugCfg config.Debug - me pbsmetrics.MetricsEngine + Bidder adapters.Bidder + Client *http.Client + DebugConfig config.Debug + me pbsmetrics.MetricsEngine } func (bidder *bidderAdapter) requestBid(ctx context.Context, request *openrtb.BidRequest, name openrtb_ext.BidderName, bidAdjustment float64, conversions currencies.Conversions, reqInfo *adapters.ExtraRequestInfo) (*pbsOrtbSeatBid, []error) { @@ -377,7 +377,7 @@ func (bidder *bidderAdapter) doTimeoutNotification(timeoutBidder adapters.Timeou httpResp, err := ctxhttp.Do(ctx, bidder.Client, httpReq) success := (err == nil && httpResp.StatusCode >= 200 && httpResp.StatusCode < 300) bidder.me.RecordTimeoutNotice(success) - if bidder.DebugCfg.TimeoutNotification.Log && !(bidder.DebugCfg.TimeoutNotification.FailOnly && success) { + if bidder.DebugConfig.TimeoutNotification.Log && !(bidder.DebugConfig.TimeoutNotification.FailOnly && success) { var msg string if err == nil { msg = fmt.Sprintf("TimeoutNotification: status:(%d) body:%s", httpResp.StatusCode, string(toReq.Body)) @@ -385,7 +385,7 @@ func (bidder *bidderAdapter) doTimeoutNotification(timeoutBidder adapters.Timeou msg = fmt.Sprintf("TimeoutNotification: error:(%s) body:%s", err.Error(), string(toReq.Body)) } // If logging is turned on, and logging is not disallowed via FailOnly - util.LogRandomSample(msg, glog.Warningf, bidder.DebugCfg.TimeoutNotification.Sampling) + util.LogRandomSample(msg, glog.Warningf, bidder.DebugConfig.TimeoutNotification.SamplingRate) } } else { bidder.me.RecordTimeoutNotice(false) From ff023530ac133845e0845183f482c7664cdf5c6e Mon Sep 17 00:00:00 2001 From: Hans Hjort Date: Tue, 9 Jun 2020 10:47:03 -0400 Subject: [PATCH 7/8] Adds missing call to validate() --- config/config.go | 1 + 1 file changed, 1 insertion(+) diff --git a/config/config.go b/config/config.go index 5a4dcd9f84b..de30db74f9d 100755 --- a/config/config.go +++ b/config/config.go @@ -106,6 +106,7 @@ func (cfg *Configuration) validate() configErrors { errs = cfg.GDPR.validate(errs) errs = cfg.CurrencyConverter.validate(errs) errs = validateAdapters(cfg.Adapters, errs) + errs = cfg.Debug.validate(errs) return errs } From 6567f29ec67e198f2c32a8b4d3e874f56285da1e Mon Sep 17 00:00:00 2001 From: Hans Hjort Date: Tue, 9 Jun 2020 10:53:40 -0400 Subject: [PATCH 8/8] Adds test for validate() --- config/config_test.go | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/config/config_test.go b/config/config_test.go index 92794d7941e..ee8e68e7025 100644 --- a/config/config_test.go +++ b/config/config_test.go @@ -426,6 +426,14 @@ func TestCookieSizeError(t *testing.T) { } } +func TestValidateDebug(t *testing.T) { + cfg := newDefaultConfig(t) + cfg.Debug.TimeoutNotification.SamplingRate = 1.1 + + err := cfg.validate() + assert.NotNil(t, err, "cfg.debug.timeout_notification.sampling_rate should not be allowed to be greater than 1.0, but it was allowed") +} + func newDefaultConfig(t *testing.T) *Configuration { v := viper.New() SetupViper(v, "")