Timeout notification monitoring and debugging (prebid#1322)

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
@@ -104,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
 }
 
@@ -450,6 +453,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
+	SamplingRate float32 `mapstructure:"sampling_rate"`
+	// Only log failures
+	FailOnly bool `mapstructure:"fail_only"`
+}
+
+func (cfg *TimeoutNotification) validate(errs configErrors) configErrors {
+	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
+}
+
 // New uses viper to get our server configurations.
 func New(v *viper.Viper) (*Configuration, error) {
 	var c Configuration
@@ -820,6 +847,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_rate", 0.0)
+	v.SetDefault("debug.timeout_notification.fail_only", false)
+
 	// Set environment variable support:
 	v.SetEnvKeyReplacer(strings.NewReplacer(".", "_"))
 	v.SetEnvPrefix("PBS")

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, "")

config/util/loggers.go

@@ -0,0 +1,24 @@
+package util
+
+import (
+	"math/rand"
+)
+
+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) {
+	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
+	}
+	logger(msg)
+}

config/util/loggers_test.go

@@ -0,0 +1,32 @@
+package util
+
+import (
+	"bytes"
+	"fmt"
+	"math/rand"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+)
+
+func TestLogRandomSample(t *testing.T) {
+
+	const expected string = `This is test line 2
+This is test line 3
+`
+
+	myRand := rand.New(rand.NewSource(1337))
+	var buf bytes.Buffer
+
+	mylogger := func(msg string, args ...interface{}) {
+		buf.WriteString(fmt.Sprintf(fmt.Sprintln(msg), args...))
+	}
+
+	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())
+}

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

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"
@@ -85,7 +87,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),
@@ -190,7 +192,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)
 		}
 	}
 

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) {

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,
+		DebugConfig: cfg.Debug,
+		me:          me,
 	}
 }
 
 type bidderAdapter struct {
-	Bidder adapters.Bidder
-	Client *http.Client
+	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) {
@@ -365,8 +374,21 @@ 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 := (err == nil && httpResp.StatusCode >= 200 && httpResp.StatusCode < 300)
+			bidder.me.RecordTimeoutNotice(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))
+				} 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.DebugConfig.TimeoutNotification.SamplingRate)
+			}
+		} else {
+			bidder.me.RecordTimeoutNotice(false)
 		}
 	}
 

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 {

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

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
 }