Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Timeout fix #1390

Merged
merged 8 commits into from
Jul 16, 2020
Merged

Timeout fix #1390

Show file tree
Hide file tree
Changes from 7 commits
Commits
Show all changes
8 commits
Select commit Hold shift + click to select a range
3a06124
Refactor to allow for deeper tests
hhhjort Jul 2, 2020
4c8af73
Deeper tests
hhhjort Jul 10, 2020
f60311a
Start unwrapping the bidder to find out if it needs notification.
hhhjort Jul 15, 2020
1d6ee61
Merge branch 'master' of https://github.com/prebid/prebid-server into…
hhhjort Jul 15, 2020
7ffe372
resolves merge conflicts
hhhjort Jul 15, 2020
0a07154
try to enforce consistent behavior
hhhjort Jul 15, 2020
160b03f
Move back to a mock bidder
hhhjort Jul 15, 2020
18c8061
Test Feedback
SyntaxNode Jul 16, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 3 additions & 3 deletions config/util/loggers.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,18 +4,18 @@ import (
"math/rand"
)

type logMsg func(string, ...interface{})
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) {
func LogRandomSample(msg string, logger LogMsg, chance float32) {
logRandomSampleImpl(msg, logger, chance, rand.Float32)
}

func logRandomSampleImpl(msg string, logger logMsg, chance float32, randGenerator randomGenerator) {
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
Expand Down
22 changes: 16 additions & 6 deletions exchange/bidder.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -312,6 +312,10 @@ 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) *httpCallInfo {
return bidder.doRequestImpl(ctx, req, glog.Warningf)
}

func (bidder *bidderAdapter) doRequestImpl(ctx context.Context, req *adapters.RequestData, logger util.LogMsg) *httpCallInfo {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we need this extra function? doRequest is not part of the interface methods and its signature can be modified.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes. The purpose of doRequest is to inject the logger. There's cleaner ways of doing this, but it requires larger refactoring which we're punting on for this PR.

httpReq, err := http.NewRequest(req.Method, req.Uri, bytes.NewBuffer(req.Body))
if err != nil {
return &httpCallInfo{
Expand All @@ -325,12 +329,18 @@ func (bidder *bidderAdapter) doRequest(ctx context.Context, req *adapters.Reques
if err != nil {
if err == context.DeadlineExceeded {
err = &errortypes.Timeout{Message: err.Error()}
if tb, ok := bidder.Bidder.(adapters.TimeoutBidder); ok {
var corebidder adapters.Bidder = bidder.Bidder
// The bidder adapter normally stores an info-aware bidder (a bidder wrapper)
// rather than the actual bidder. So we need to unpack that first.
if b, ok := corebidder.(*adapters.InfoAwareBidder); ok {
corebidder = b.Bidder
}
if tb, ok := corebidder.(adapters.TimeoutBidder); ok {
// Toss the timeout notification call into a go routine, as we are out of time'
// and cannot delay processing. We don't do anything result, as there is not much
// we can do about a timeout notification failure. We do not want to get stuck in
// a loop of trying to report timeouts to the timeout notifications.
go bidder.doTimeoutNotification(tb, req)
go bidder.doTimeoutNotification(tb, req, logger)
}

}
Expand Down Expand Up @@ -366,7 +376,7 @@ func (bidder *bidderAdapter) doRequest(ctx context.Context, req *adapters.Reques
}
}

func (bidder *bidderAdapter) doTimeoutNotification(timeoutBidder adapters.TimeoutBidder, req *adapters.RequestData) {
func (bidder *bidderAdapter) doTimeoutNotification(timeoutBidder adapters.TimeoutBidder, req *adapters.RequestData, logger util.LogMsg) {
ctx, cancel := context.WithTimeout(context.Background(), 200*time.Millisecond)
defer cancel()
toReq, errL := timeoutBidder.MakeTimeoutNotification(req)
Expand All @@ -385,13 +395,13 @@ 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.DebugConfig.TimeoutNotification.SamplingRate)
util.LogRandomSample(msg, logger, bidder.DebugConfig.TimeoutNotification.SamplingRate)
}
} else {
bidder.me.RecordTimeoutNotice(false)
if bidder.DebugConfig.TimeoutNotification.Log {
msg := fmt.Sprintf("TimeoutNotification: Failed to make timeout request: method(%s), uri(%s), error(%s)", toReq.Method, toReq.Uri, err.Error())
util.LogRandomSample(msg, glog.Warningf, bidder.DebugConfig.TimeoutNotification.SamplingRate)
util.LogRandomSample(msg, logger, bidder.DebugConfig.TimeoutNotification.SamplingRate)
}
}
} else if bidder.DebugConfig.TimeoutNotification.Log {
Expand All @@ -402,7 +412,7 @@ func (bidder *bidderAdapter) doTimeoutNotification(timeoutBidder adapters.Timeou
} else {
msg = fmt.Sprintf("TimeoutNotification: Failed to generate timeout request: error(%s), bidder request marshal failed(%s)", errL[0].Error(), err.Error())
}
util.LogRandomSample(msg, glog.Warningf, bidder.DebugConfig.TimeoutNotification.SamplingRate)
util.LogRandomSample(msg, logger, bidder.DebugConfig.TimeoutNotification.SamplingRate)
}

}
Expand Down
51 changes: 43 additions & 8 deletions exchange/bidder_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
package exchange

import (
"bytes"
"context"
"encoding/json"
"errors"
Expand All @@ -10,6 +11,7 @@ import (
"testing"
"time"

"github.com/golang/glog"
"github.com/mxmCherry/openrtb"
"github.com/prebid/prebid-server/adapters"
"github.com/prebid/prebid-server/config"
Expand Down Expand Up @@ -1254,15 +1256,28 @@ func TestTimeoutNotificationOff(t *testing.T) {
if tb, ok := bidder.Bidder.(adapters.TimeoutBidder); !ok {
t.Error("Failed to cast bidder to a TimeoutBidder")
} else {
bidder.doTimeoutNotification(tb, &adapters.RequestData{})
bidder.doTimeoutNotification(tb, &adapters.RequestData{}, glog.Warningf)
}
}

func TestTimeoutNotificationOn(t *testing.T) {
ctx, cancelFunc := context.WithDeadline(context.Background(), time.Now().Add(-7*time.Hour))
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Does the time matter since we're cancelling the context immediately? If so, consider using just time.Now() or perhaps time.Time{}.

cancelFunc()
respBody := "{\"bid\":false}"
respStatus := 200
server := httptest.NewServer(mockHandler(respStatus, "getBody", respBody))
server := httptest.NewServer(mockSlowHandler(respStatus, "getBody", respBody))
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The slow handler waits 500ms. I think that's too long for a unit test. Ideally we'd inject a mock context to the timeout caller, but since we can't I think using smaller timeouts is a good compromise. Let's use 201ms or 205ms since the method is hardcoded for 200ms.

defer server.Close()
bidRequest := adapters.RequestData{
Method: "POST",
Uri: server.URL,
Body: []byte("{\"id\":\"this-id\",\"app\":{\"publisher\":{\"id\":\"pub-id\"}}}"),
}

var buf bytes.Buffer

mylogger := func(msg string, args ...interface{}) {
buf.WriteString(fmt.Sprintf(fmt.Sprintln(msg), args...))
}

bidderImpl := &notifingBidder{
notiRequest: adapters.RequestData{
Expand All @@ -1272,21 +1287,40 @@ func TestTimeoutNotificationOn(t *testing.T) {
Headers: http.Header{},
},
}
// bidderImpl := audienceNetwork.NewFacebookBidder("test-platform-id", "test-app-secret")
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Consider removing the comment.

bidderInfo := adapters.BidderInfo{
Status: adapters.StatusActive,
Capabilities: &adapters.CapabilitiesInfo{
App: &adapters.PlatformInfo{
MediaTypes: []openrtb_ext.BidType{openrtb_ext.BidTypeBanner},
},
},
}
ibidder := adapters.EnforceBidderInfo(bidderImpl, bidderInfo)
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

IMO it would be nice to bundle this along with the bidderImpl assignment above it and make it a function call like createInfoAwareBidder for readability purposes.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

iBidder isn't very descriptive. Consider wrappedBidder.

bidder := &bidderAdapter{
Bidder: bidderImpl,
Bidder: ibidder,
Client: server.Client(),
DebugConfig: config.Debug{
TimeoutNotification: config.TimeoutNotification{
Log: true,
Log: true,
SamplingRate: 1.0,
},
},
me: &metricsConfig.DummyMetricsEngine{},
}
if tb, ok := bidder.Bidder.(adapters.TimeoutBidder); !ok {
t.Error("Failed to cast bidder to a TimeoutBidder")
var corebidder adapters.Bidder = bidder.Bidder
if b, ok := corebidder.(*adapters.InfoAwareBidder); ok {
corebidder = b.Bidder
}
if _, ok := corebidder.(adapters.TimeoutBidder); !ok {
t.Fatal("Failed to cast bidder to a TimeoutBidder")
SyntaxNode marked this conversation as resolved.
Show resolved Hide resolved
} else {
bidder.doTimeoutNotification(tb, &adapters.RequestData{})
bidder.doRequestImpl(ctx, &bidRequest, mylogger)
}
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What if the logic inside doRequest changes? this logic would no longer apply, would it?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It would not. The entire auction core is in our sights for a refactor soon.

time.Sleep(300 * time.Millisecond)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We can probably lower this to around 210ms.

expected := "TimeoutNotification: error:(context deadline exceeded) body:\n"
actual := buf.String()
assert.EqualValues(t, expected, actual)
}

type goodSingleBidder struct {
Expand Down Expand Up @@ -1364,11 +1398,12 @@ func (bidder *bidRejector) MakeBids(internalRequest *openrtb.BidRequest, externa
}

type notifingBidder struct {
requests []*adapters.RequestData
notiRequest adapters.RequestData
}

func (bidder *notifingBidder) MakeRequests(request *openrtb.BidRequest, reqInfo *adapters.ExtraRequestInfo) ([]*adapters.RequestData, []error) {
return nil, nil
return bidder.requests, nil
}

func (bidder *notifingBidder) MakeBids(internalRequest *openrtb.BidRequest, externalRequest *adapters.RequestData, response *adapters.ResponseData) (*adapters.BidderResponse, []error) {
Expand Down
12 changes: 12 additions & 0 deletions exchange/exchange_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1830,6 +1830,18 @@ func mockHandler(statusCode int, getBody string, postBody string) http.Handler {
})
}

func mockSlowHandler(statusCode int, getBody string, postBody string) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
time.Sleep(500 * time.Millisecond)
w.WriteHeader(statusCode)
if r.Method == "GET" {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think the method type is important for the test. Consider accepting a single body string and always return it.

w.Write([]byte(getBody))
} else {
w.Write([]byte(postBody))
}
})
}

type wellBehavedCache struct{}

func (c *wellBehavedCache) GetExtCacheData() (string, string) {
Expand Down