Timeout fix (prebid#1390)

config/util/loggers.go

@@ -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

exchange/bidder.go

@@ -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 {
 	httpReq, err := http.NewRequest(req.Method, req.Uri, bytes.NewBuffer(req.Body))
 	if err != nil {
 		return &httpCallInfo{
@@ -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)
 			}
 
 		}
@@ -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)
@@ -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 {
@@ -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)
 	}
 
 }

exchange/bidder_test.go

@@ -1,6 +1,7 @@
 package exchange
 
 import (
+	"bytes"
 	"context"
 	"encoding/json"
 	"errors"
@@ -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"
@@ -1237,8 +1239,8 @@ func TestTimeoutNotificationOff(t *testing.T) {
 	server := httptest.NewServer(mockHandler(respStatus, "getBody", respBody))
 	defer server.Close()
 
-	bidderImpl := &notifingBidder{
-		notiRequest: adapters.RequestData{
+	bidderImpl := &notifyingBidder{
+		notifyRequest: adapters.RequestData{
 			Method:  "GET",
 			Uri:     server.URL + "/notify/me",
 			Body:    nil,
@@ -1254,39 +1256,83 @@ 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) {
-	respBody := "{\"bid\":false}"
-	respStatus := 200
-	server := httptest.NewServer(mockHandler(respStatus, "getBody", respBody))
+	// Expire context immediately to force timeout handler.
+	ctx, cancelFunc := context.WithDeadline(context.Background(), time.Now())
+	cancelFunc()
+
+	// Notification logic is hardcoded for 200ms. We need to wait for a little longer than that.
+	server := httptest.NewServer(mockSlowHandler(205*time.Millisecond, 200, `{"bid":false}`))
 	defer server.Close()
 
-	bidderImpl := &notifingBidder{
-		notiRequest: adapters.RequestData{
+	bidder := &notifyingBidder{
+		notifyRequest: adapters.RequestData{
 			Method:  "GET",
 			Uri:     server.URL + "/notify/me",
 			Body:    nil,
 			Headers: http.Header{},
 		},
 	}
-	bidder := &bidderAdapter{
-		Bidder: bidderImpl,
+
+	// Wrap with BidderInfo to mimic exchange.go flow.
+	bidderWrappedWithInfo := wrapWithBidderInfo(bidder)
+
+	bidderAdapter := &bidderAdapter{
+		Bidder: bidderWrappedWithInfo,
 		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")
-	} else {
-		bidder.doTimeoutNotification(tb, &adapters.RequestData{})
+
+	// Unwrap To Mimic exchange.go Casting Code
+	var coreBidder adapters.Bidder = bidderAdapter.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")
+	}
+
+	bidRequest := adapters.RequestData{
+		Method: "POST",
+		Uri:    server.URL,
+		Body:   []byte(`{"id":"this-id","app":{"publisher":{"id":"pub-id"}}}`),
+	}
+
+	var loggerBuffer bytes.Buffer
+	logger := func(msg string, args ...interface{}) {
+		loggerBuffer.WriteString(fmt.Sprintf(fmt.Sprintln(msg), args...))
+	}
+
+	bidderAdapter.doRequestImpl(ctx, &bidRequest, logger)
+
+	// Wait a little longer than the 205ms mock server sleep.
+	time.Sleep(210 * time.Millisecond)
+
+	logExpected := "TimeoutNotification: error:(context deadline exceeded) body:\n"
+	logActual := loggerBuffer.String()
+	assert.EqualValues(t, logExpected, logActual)
+}
+
+func wrapWithBidderInfo(bidder adapters.Bidder) adapters.Bidder {
+	bidderInfo := adapters.BidderInfo{
+		Status: adapters.StatusActive,
+		Capabilities: &adapters.CapabilitiesInfo{
+			App: &adapters.PlatformInfo{
+				MediaTypes: []openrtb_ext.BidType{openrtb_ext.BidTypeBanner},
+			},
+		},
 	}
+	return adapters.EnforceBidderInfo(bidder, bidderInfo)
 }
 
 type goodSingleBidder struct {
@@ -1363,18 +1409,19 @@ func (bidder *bidRejector) MakeBids(internalRequest *openrtb.BidRequest, externa
 	return nil, []error{errors.New("Can't make a response.")}
 }
 
-type notifingBidder struct {
-	notiRequest adapters.RequestData
+type notifyingBidder struct {
+	requests      []*adapters.RequestData
+	notifyRequest adapters.RequestData
 }
 
-func (bidder *notifingBidder) MakeRequests(request *openrtb.BidRequest, reqInfo *adapters.ExtraRequestInfo) ([]*adapters.RequestData, []error) {
-	return nil, nil
+func (bidder *notifyingBidder) MakeRequests(request *openrtb.BidRequest, reqInfo *adapters.ExtraRequestInfo) ([]*adapters.RequestData, []error) {
+	return bidder.requests, nil
 }
 
-func (bidder *notifingBidder) MakeBids(internalRequest *openrtb.BidRequest, externalRequest *adapters.RequestData, response *adapters.ResponseData) (*adapters.BidderResponse, []error) {
+func (bidder *notifyingBidder) MakeBids(internalRequest *openrtb.BidRequest, externalRequest *adapters.RequestData, response *adapters.ResponseData) (*adapters.BidderResponse, []error) {
 	return nil, nil
 }
 
-func (bidder *notifingBidder) MakeTimeoutNotification(req *adapters.RequestData) (*adapters.RequestData, []error) {
-	return &bidder.notiRequest, nil
+func (bidder *notifyingBidder) MakeTimeoutNotification(req *adapters.RequestData) (*adapters.RequestData, []error) {
+	return &bidder.notifyRequest, nil
 }

exchange/exchange_test.go

@@ -1830,6 +1830,15 @@ func mockHandler(statusCode int, getBody string, postBody string) http.Handler {
 	})
 }
 
+func mockSlowHandler(delay time.Duration, statusCode int, body string) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		time.Sleep(delay)
+
+		w.WriteHeader(statusCode)
+		w.Write([]byte(body))
+	})
+}
+
 type wellBehavedCache struct{}
 
 func (c *wellBehavedCache) GetExtCacheData() (string, string) {