Skip to content

Commit

Permalink
Add BidderResponseDurationMin check (#2848)
Browse files Browse the repository at this point in the history 
co-authored by @onkarvhanumante
  • Loading branch information
@onkarvhanumante
onkarvhanumante authored Jul 31, 2023
1 parent 16b7013 commit 8ffa1c6
Show file tree
Hide file tree
Showing 8 changed files with 186 additions and 43 deletions.
2 changes: 0 additions & 2 deletions adapters/bidder.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -4,7 +4,6 @@ import (
"encoding/base64"
"encoding/json"
"net/http"
"time"

"github.com/prebid/openrtb/v19/openrtb2"
"github.com/prebid/prebid-server/config"
Expand Down Expand Up @@ -146,7 +145,6 @@ func (r *RequestData) SetBasicAuth(username string, password string) {

type ExtraRequestInfo struct {
PbsEntryPoint metrics.RequestType
BidderRequestStartTime time.Time
GlobalPrivacyControlHeader string
CurrencyConversions currency.Conversions
}
Expand Down
3 changes: 0 additions & 3 deletions endpoints/openrtb2/amp_auction.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -296,9 +296,6 @@ func (deps *endpointDeps) AmpAuction(w http.ResponseWriter, r *http.Request, _ h
}

labels, ao = sendAmpResponse(w, hookExecutor, auctionResponse, reqWrapper, account, labels, ao, errL)
if len(ao.Errors) == 0 && !auctionRequest.BidderResponseStartTime.IsZero() {
deps.metricsEngine.RecordOverheadTime(metrics.MakeAuctionResponse, time.Since(auctionRequest.BidderResponseStartTime))
}
}

func rejectAmpRequest(
Expand Down
3 changes: 0 additions & 3 deletions endpoints/openrtb2/auction.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -292,9 +292,6 @@ func (deps *endpointDeps) Auction(w http.ResponseWriter, r *http.Request, _ http
glog.Errorf("Error setting seat non-bid: %v", err)
}
labels, ao = sendAuctionResponse(w, hookExecutor, response, req.BidRequest, account, labels, ao)
if len(ao.Errors) == 0 && !auctionRequest.BidderResponseStartTime.IsZero() {
deps.metricsEngine.RecordOverheadTime(metrics.MakeAuctionResponse, time.Since(auctionRequest.BidderResponseStartTime))
}
}

// setSeatNonBidRaw is transitional function for setting SeatNonBid inside bidResponse.Ext
Expand Down
4 changes: 0 additions & 4 deletions endpoints/openrtb2/video_auction.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -375,10 +375,6 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re
return
}

if len(vo.Errors) == 0 && !auctionRequest.BidderResponseStartTime.IsZero() {
deps.metricsEngine.RecordOverheadTime(metrics.MakeAuctionResponse, time.Since(auctionRequest.BidderResponseStartTime))
}

w.Header().Set("Content-Type", "application/json")
w.Write(resp)

Expand Down
48 changes: 37 additions & 11 deletions exchange/bidder.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -63,11 +63,12 @@ type AdaptedBidder interface {

// bidRequestOptions holds additional options for bid request execution to maintain clean code and reasonable number of parameters
type bidRequestOptions struct {
accountDebugAllowed bool
headerDebugAllowed bool
addCallSignHeader bool
bidAdjustments map[string]float64
tmaxAdjustments *TmaxAdjustmentsPreprocessed
accountDebugAllowed bool
headerDebugAllowed bool
addCallSignHeader bool
bidAdjustments map[string]float64
tmaxAdjustments *TmaxAdjustmentsPreprocessed
bidderRequestStartTime time.Time
}

type extraBidderRespInfo struct {
Expand All @@ -87,6 +88,8 @@ const (
Gzip string = "GZIP"
)

var errTmaxTimeout = errors.New("exceeded tmax duration")

// AdaptBidder converts an adapters.Bidder into an exchange.AdaptedBidder.
//
// The name refers to the "Adapter" architecture pattern, and should not be confused with a Prebid "Adapter"
Expand Down Expand Up @@ -190,11 +193,11 @@ func (bidder *bidderAdapter) requestBid(ctx context.Context, bidderRequest Bidde
dataLen = len(reqData) + len(bidderRequest.BidderStoredResponses)
responseChannel = make(chan *httpCallInfo, dataLen)
if len(reqData) == 1 {
responseChannel <- bidder.doRequest(ctx, reqData[0], reqInfo.BidderRequestStartTime)
responseChannel <- bidder.doRequest(ctx, reqData[0], bidRequestOptions.bidderRequestStartTime, bidRequestOptions.tmaxAdjustments)
} else {
for _, oneReqData := range reqData {
go func(data *adapters.RequestData) {
responseChannel <- bidder.doRequest(ctx, data, reqInfo.BidderRequestStartTime)
responseChannel <- bidder.doRequest(ctx, data, bidRequestOptions.bidderRequestStartTime, bidRequestOptions.tmaxAdjustments)
}(oneReqData) // Method arg avoids a race condition on oneReqData
}
}
Expand Down Expand Up @@ -513,11 +516,11 @@ func makeExt(httpInfo *httpCallInfo) *openrtb_ext.ExtHttpCall {

// doRequest makes a request, handles the response, and returns the data needed by the
// Bidder interface.
func (bidder *bidderAdapter) doRequest(ctx context.Context, req *adapters.RequestData, pbsRequestStartTime time.Time) *httpCallInfo {
return bidder.doRequestImpl(ctx, req, glog.Warningf, pbsRequestStartTime)
func (bidder *bidderAdapter) doRequest(ctx context.Context, req *adapters.RequestData, bidderRequestStartTime time.Time, tmaxAdjustments *TmaxAdjustmentsPreprocessed) *httpCallInfo {
return bidder.doRequestImpl(ctx, req, glog.Warningf, bidderRequestStartTime, tmaxAdjustments)
}

func (bidder *bidderAdapter) doRequestImpl(ctx context.Context, req *adapters.RequestData, logger util.LogMsg, pbsRequestStartTime time.Time) *httpCallInfo {
func (bidder *bidderAdapter) doRequestImpl(ctx context.Context, req *adapters.RequestData, logger util.LogMsg, bidderRequestStartTime time.Time, tmaxAdjustments *TmaxAdjustmentsPreprocessed) *httpCallInfo {
var requestBody []byte

switch strings.ToUpper(bidder.config.EndpointCompression) {
Expand All @@ -541,7 +544,17 @@ func (bidder *bidderAdapter) doRequestImpl(ctx context.Context, req *adapters.Re
if !bidder.config.DisableConnMetrics {
ctx = bidder.addClientTrace(ctx)
}
bidder.me.RecordOverheadTime(metrics.PreBidder, time.Since(pbsRequestStartTime))
bidder.me.RecordOverheadTime(metrics.PreBidder, time.Since(bidderRequestStartTime))

if tmaxAdjustments != nil && tmaxAdjustments.IsEnforced {
if hasShorterDurationThanTmax(&bidderTmaxCtx{ctx}, *tmaxAdjustments) {
return &httpCallInfo{
request: req,
err: errTmaxTimeout,
}
}
}

httpCallStart := time.Now()
httpResp, err := ctxhttp.Do(ctx, bidder.Client, httpReq)
if err != nil {
Expand Down Expand Up @@ -724,3 +737,16 @@ func getBidTypeForAdjustments(bidType openrtb_ext.BidType, impID string, imp []o
}
return string(bidType)
}

func hasShorterDurationThanTmax(ctx bidderTmaxContext, tmaxAdjustments TmaxAdjustmentsPreprocessed) bool {
if tmaxAdjustments.IsEnforced {
if deadline, ok := ctx.Deadline(); ok {
overheadNS := time.Duration(tmaxAdjustments.BidderNetworkLatencyBuffer+tmaxAdjustments.PBSResponsePreparationDuration) * time.Millisecond
bidderTmax := deadline.Add(-overheadNS)

remainingDuration := ctx.Until(bidderTmax).Milliseconds()
return remainingDuration < int64(tmaxAdjustments.BidderResponseDurationMin)
}
}
return false
}
151 changes: 137 additions & 14 deletions exchange/bidder_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -555,11 +555,11 @@ func TestBidderTimeout(t *testing.T) {
Client: server.Client(),
me: &metricsConfig.NilMetricsEngine{},
}

tmaxAdjustments := &TmaxAdjustmentsPreprocessed{}
callInfo := bidder.doRequest(ctx, &adapters.RequestData{
Method: "POST",
Uri: server.URL,
}, time.Now())
}, time.Now(), tmaxAdjustments)
if callInfo.err == nil {
t.Errorf("The bidder should report an error if the context has expired already.")
}
Expand All @@ -575,10 +575,10 @@ func TestInvalidRequest(t *testing.T) {
Bidder: &mixedMultiBidder{},
Client: server.Client(),
}

tmaxAdjustments := &TmaxAdjustmentsPreprocessed{}
callInfo := bidder.doRequest(context.Background(), &adapters.RequestData{
Method: "\"", // force http.NewRequest() to fail
}, time.Now())
}, time.Now(), tmaxAdjustments)
if callInfo.err == nil {
t.Errorf("bidderAdapter.doRequest should return an error if the request data is malformed.")
}
Expand All @@ -598,11 +598,11 @@ func TestConnectionClose(t *testing.T) {
BidderName: openrtb_ext.BidderAppnexus,
me: &metricsConfig.NilMetricsEngine{},
}

tmaxAdjustments := &TmaxAdjustmentsPreprocessed{}
callInfo := bidder.doRequest(context.Background(), &adapters.RequestData{
Method: "POST",
Uri: server.URL,
}, time.Now())
}, time.Now(), tmaxAdjustments)
if callInfo.err == nil {
t.Errorf("bidderAdapter.doRequest should return an error if the connection closes unexpectedly.")
}
Expand Down Expand Up @@ -2107,9 +2107,10 @@ func TestCallRecordDNSTime(t *testing.T) {
Client: &http.Client{Transport: DNSDoneTripper{}},
me: metricsMock,
}
tmaxAdjustments := &TmaxAdjustmentsPreprocessed{}

// Run test
bidder.doRequest(context.Background(), &adapters.RequestData{Method: "POST", Uri: "http://www.example.com/"}, time.Now())
bidder.doRequest(context.Background(), &adapters.RequestData{Method: "POST", Uri: "http://www.example.com/"}, time.Now(), tmaxAdjustments)

// Tried one or another, none seem to work without panicking
metricsMock.AssertExpectations(t)
Expand All @@ -2130,9 +2131,10 @@ func TestCallRecordTLSHandshakeTime(t *testing.T) {
Client: &http.Client{Transport: TLSHandshakeTripper{}},
me: metricsMock,
}
tmaxAdjustments := &TmaxAdjustmentsPreprocessed{}

// Run test
bidder.doRequest(context.Background(), &adapters.RequestData{Method: "POST", Uri: "http://www.example.com/"}, time.Now())
bidder.doRequest(context.Background(), &adapters.RequestData{Method: "POST", Uri: "http://www.example.com/"}, time.Now(), tmaxAdjustments)

// Tried one or another, none seem to work without panicking
metricsMock.AssertExpectations(t)
Expand Down Expand Up @@ -2219,8 +2221,8 @@ func TestTimeoutNotificationOn(t *testing.T) {
logger := func(msg string, args ...interface{}) {
loggerBuffer.WriteString(fmt.Sprintf(fmt.Sprintln(msg), args...))
}

bidderAdapter.doRequestImpl(ctx, &bidRequest, logger, time.Now())
tmaxAdjustments := &TmaxAdjustmentsPreprocessed{}
bidderAdapter.doRequestImpl(ctx, &bidRequest, logger, time.Now(), tmaxAdjustments)

// Wait a little longer than the 205ms mock server sleep.
time.Sleep(210 * time.Millisecond)
Expand Down Expand Up @@ -3065,8 +3067,8 @@ func TestGetBidType(t *testing.T) {
}

type mockBidderTmaxCtx struct {
startTime, deadline time.Time
ok bool
startTime, deadline, now time.Time
ok bool
}

func (m *mockBidderTmaxCtx) Deadline() (deadline time.Time, _ bool) {
Expand All @@ -3076,6 +3078,10 @@ func (m *mockBidderTmaxCtx) RemainingDurationMS(deadline time.Time) int64 {
return deadline.Sub(m.startTime).Milliseconds()
}

func (m *mockBidderTmaxCtx) Until(t time.Time) time.Duration {
return t.Sub(m.now)
}

func TestUpdateBidderTmax(t *testing.T) {
respStatus := 200
respBody := "{\"bid\":false}"
Expand Down Expand Up @@ -3129,13 +3135,130 @@ func TestUpdateBidderTmax(t *testing.T) {
bidResponse: &adapters.BidderResponse{},
}

ctx, cancel := context.WithDeadline(context.Background(), time.Now().Add(50*time.Millisecond))
now := time.Now()
ctx, cancel := context.WithDeadline(context.Background(), now.Add(500*time.Millisecond))
defer cancel()
bidReqOptions := bidRequestOptions{tmaxAdjustments: test.tmaxAdjustments}
bidReqOptions := bidRequestOptions{bidderRequestStartTime: now, tmaxAdjustments: test.tmaxAdjustments}
bidder := AdaptBidder(bidderImpl, server.Client(), &config.Configuration{}, &metricsConfig.NilMetricsEngine{}, openrtb_ext.BidderAppnexus, &config.DebugInfo{Allow: false}, "")
_, _, errs := bidder.requestBid(ctx, bidderReq, currencyConverter.Rates(), extraInfo, &adscert.NilSigner{}, bidReqOptions, openrtb_ext.ExtAlternateBidderCodes{}, &hookexecution.EmptyHookExecutor{}, nil)
assert.Empty(t, errs)
assert.True(t, test.assertFn(bidderImpl.bidRequest.TMax))
})
}
}

func TestHasShorterDurationThanTmax(t *testing.T) {
var requestTmaxMS int64 = 700
requestTmaxNS := requestTmaxMS * int64(time.Millisecond)
startTime := time.Date(2023, 5, 30, 1, 0, 0, 0, time.UTC)
now := time.Date(2023, 5, 30, 1, 0, 0, int(200*time.Millisecond), time.UTC)
deadline := time.Date(2023, 5, 30, 1, 0, 0, int(requestTmaxNS), time.UTC)
ctx := &mockBidderTmaxCtx{startTime: startTime, deadline: deadline, now: now, ok: true}

tests := []struct {
description string
ctx bidderTmaxContext
requestTmax int64
tmaxAdjustments TmaxAdjustmentsPreprocessed
expected bool
}{
{
description: "tmax-disabled",
ctx: ctx,
requestTmax: requestTmaxMS,
tmaxAdjustments: TmaxAdjustmentsPreprocessed{IsEnforced: false},
expected: false,
},
{
description: "remaing-duration-greater-than-bidder-response-min",
ctx: ctx,
requestTmax: requestTmaxMS,
tmaxAdjustments: TmaxAdjustmentsPreprocessed{IsEnforced: true, PBSResponsePreparationDuration: 50, BidderNetworkLatencyBuffer: 10, BidderResponseDurationMin: 40},
expected: false,
},
{
description: "remaing-duration-less-than-bidder-response-min",
ctx: ctx,
requestTmax: requestTmaxMS,
tmaxAdjustments: TmaxAdjustmentsPreprocessed{IsEnforced: true, PBSResponsePreparationDuration: 100, BidderNetworkLatencyBuffer: 10, BidderResponseDurationMin: 500},
expected: true,
},
}

for _, test := range tests {
t.Run(test.description, func(t *testing.T) {
assert.Equal(t, test.expected, hasShorterDurationThanTmax(test.ctx, test.tmaxAdjustments))
})
}
}

func TestDoRequestImplWithTmax(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"}}}`),
}

bidderAdapter := bidderAdapter{
me: &metricsConfig.NilMetricsEngine{},
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) },
},
{
ctxDeadline: time.Now().Add(5 * time.Second),
description: "remaining-duration-greater-than-tmax-min",
tmaxAdjustments: &TmaxAdjustmentsPreprocessed{IsEnforced: true, PBSResponsePreparationDuration: 100, BidderNetworkLatencyBuffer: 10, BidderResponseDurationMin: 100},
assertFn: func(err error) { assert.Nil(t, err) },
},
{
description: "tmax-disabled",
tmaxAdjustments: &TmaxAdjustmentsPreprocessed{IsEnforced: false},
assertFn: func(err error) { assert.Nil(t, err) },
},
{
description: "tmax-BidderResponseDurationMin-not-set",
tmaxAdjustments: &TmaxAdjustmentsPreprocessed{IsEnforced: true, BidderResponseDurationMin: 0},
assertFn: func(err error) { assert.Nil(t, err) },
},
{
description: "tmax-is-nil",
tmaxAdjustments: nil,
assertFn: func(err error) { assert.Nil(t, 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)
}
}
12 changes: 6 additions & 6 deletions exchange/exchange.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -695,14 +695,14 @@ func (e *exchange) getAllBids(
reqInfo := adapters.NewExtraRequestInfo(conversions)
reqInfo.PbsEntryPoint = bidderRequest.BidderLabels.RType
reqInfo.GlobalPrivacyControlHeader = globalPrivacyControlHeader
reqInfo.BidderRequestStartTime = start

bidReqOptions := bidRequestOptions{
accountDebugAllowed: accountDebugAllowed,
headerDebugAllowed: headerDebugAllowed,
addCallSignHeader: isAdsCertEnabled(experiment, e.bidderInfo[string(bidderRequest.BidderName)]),
bidAdjustments: bidAdjustments,
tmaxAdjustments: tmaxAdjustments,
accountDebugAllowed: accountDebugAllowed,
headerDebugAllowed: headerDebugAllowed,
addCallSignHeader: isAdsCertEnabled(experiment, e.bidderInfo[string(bidderRequest.BidderName)]),
bidAdjustments: bidAdjustments,
tmaxAdjustments: tmaxAdjustments,
bidderRequestStartTime: start,
}
seatBids, extraBidderRespInfo, err := e.adapterMap[bidderRequest.BidderCoreName].requestBid(ctx, bidderRequest, conversions, &reqInfo, e.adsCertSigner, bidReqOptions, alternateBidderCodes, hookExecutor, bidAdjustmentRules)
brw.bidderResponseStartTime = extraBidderRespInfo.respProcessingStartTime
Expand Down
Loading

0 comments on commit 8ffa1c6

Please sign in to comment.