Extra logging for timeout notifications (prebid#1349)

Author: hhhjort

exchange/bidder.go

@@ -389,7 +389,20 @@ func (bidder *bidderAdapter) doTimeoutNotification(timeoutBidder adapters.Timeou
 			}
 		} 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)
+			}
+		}
+	} else if bidder.DebugConfig.TimeoutNotification.Log {
+		reqJSON, err := json.Marshal(req)
+		var msg string
+		if err == nil {
+			msg = fmt.Sprintf("TimeoutNotification: Failed to generate timeout request: error(%s), bidder request(%s)", errL[0].Error(), string(reqJSON))
+		} 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)
 	}
 
 }

exchange/bidder_test.go

@@ -1229,6 +1229,64 @@ func TestSetAssetTypes(t *testing.T) {
 	}
 }
 
+func TestTimeoutNotificationOff(t *testing.T) {
+	respBody := "{\"bid\":false}"
+	respStatus := 200
+	server := httptest.NewServer(mockHandler(respStatus, "getBody", respBody))
+	defer server.Close()
+
+	bidderImpl := &notifingBidder{
+		notiRequest: adapters.RequestData{
+			Method:  "GET",
+			Uri:     server.URL + "/notify/me",
+			Body:    nil,
+			Headers: http.Header{},
+		},
+	}
+	bidder := &bidderAdapter{
+		Bidder:      bidderImpl,
+		Client:      server.Client(),
+		DebugConfig: config.Debug{},
+		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{})
+	}
+}
+
+func TestTimeoutNotificationOn(t *testing.T) {
+	respBody := "{\"bid\":false}"
+	respStatus := 200
+	server := httptest.NewServer(mockHandler(respStatus, "getBody", respBody))
+	defer server.Close()
+
+	bidderImpl := &notifingBidder{
+		notiRequest: adapters.RequestData{
+			Method:  "GET",
+			Uri:     server.URL + "/notify/me",
+			Body:    nil,
+			Headers: http.Header{},
+		},
+	}
+	bidder := &bidderAdapter{
+		Bidder: bidderImpl,
+		Client: server.Client(),
+		DebugConfig: config.Debug{
+			TimeoutNotification: config.TimeoutNotification{
+				Log: true,
+			},
+		},
+		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{})
+	}
+}
+
 type goodSingleBidder struct {
 	bidRequest   *openrtb.BidRequest
 	httpRequest  *adapters.RequestData
@@ -1302,3 +1360,19 @@ func (bidder *bidRejector) MakeBids(internalRequest *openrtb.BidRequest, externa
 	bidder.httpResponse = response
 	return nil, []error{errors.New("Can't make a response.")}
 }
+
+type notifingBidder struct {
+	notiRequest adapters.RequestData
+}
+
+func (bidder *notifingBidder) MakeRequests(request *openrtb.BidRequest, reqInfo *adapters.ExtraRequestInfo) ([]*adapters.RequestData, []error) {
+	return nil, nil
+}
+
+func (bidder *notifingBidder) 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
+}