Further code cleanup and added unit tests for debug changes

endpoints/openrtb2/amp_auction.go

@@ -166,7 +166,7 @@ func (deps *endpointDeps) AmpAuction(w http.ResponseWriter, r *http.Request, _ h
 		return
 	}
 
-	response, err := deps.ex.HoldAuction(ctx, req, usersyncs, labels, &deps.categories, "")
+	response, err := deps.ex.HoldAuction(ctx, req, usersyncs, labels, &deps.categories, nil)
 	ao.AuctionResponse = response
 
 	if err != nil {

endpoints/openrtb2/amp_auction_test.go

@@ -11,7 +11,6 @@ import (
 	"strconv"
 	"testing"
 
-	"github.com/prebid/prebid-server/prebid_cache_client"
 	"github.com/prebid/prebid-server/stored_requests"
 	"github.com/prebid/prebid-server/stored_requests/backends/empty_fetcher"
 
@@ -903,7 +902,7 @@ type mockAmpExchange struct {
 	lastRequest *openrtb.BidRequest
 }
 
-func (m *mockAmpExchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, ids exchange.IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, debugLog string) (*openrtb.BidResponse, error) {
+func (m *mockAmpExchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, ids exchange.IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, debugLog *exchange.DebugLog) (*openrtb.BidResponse, error) {
 	m.lastRequest = bidRequest
 
 	response := &openrtb.BidResponse{
@@ -927,10 +926,6 @@ func (m *mockAmpExchange) HoldAuction(ctx context.Context, bidRequest *openrtb.B
 	return response, nil
 }
 
-func (m *mockAmpExchange) GetCache() prebid_cache_client.Client {
-	return nil
-}
-
 func getTestBidRequest(nilUser bool, nilExt bool, consentString string, digitrustID string) ([]byte, error) {
 	var userExt openrtb_ext.ExtUser
 	var userExtData []byte

endpoints/openrtb2/auction.go

@@ -140,7 +140,7 @@ func (deps *endpointDeps) Auction(w http.ResponseWriter, r *http.Request, _ http
 		return
 	}
 
-	response, err := deps.ex.HoldAuction(ctx, req, usersyncs, labels, &deps.categories, "")
+	response, err := deps.ex.HoldAuction(ctx, req, usersyncs, labels, &deps.categories, nil)
 	ao.Request = req
 	ao.Response = response
 	if err != nil {

endpoints/openrtb2/auction_test.go

@@ -16,7 +16,6 @@ import (
 	"time"
 
 	"github.com/prebid/prebid-server/adapters"
-	"github.com/prebid/prebid-server/prebid_cache_client"
 	"github.com/prebid/prebid-server/stored_requests"
 	metrics "github.com/rcrowley/go-metrics"
 
@@ -960,7 +959,7 @@ type nobidExchange struct {
 	gotRequest *openrtb.BidRequest
 }
 
-func (e *nobidExchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, ids exchange.IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, debugLog string) (*openrtb.BidResponse, error) {
+func (e *nobidExchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, ids exchange.IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, debugLog *exchange.DebugLog) (*openrtb.BidResponse, error) {
 	e.gotRequest = bidRequest
 	return &openrtb.BidResponse{
 		ID:    bidRequest.ID,
@@ -969,20 +968,12 @@ func (e *nobidExchange) HoldAuction(ctx context.Context, bidRequest *openrtb.Bid
 	}, nil
 }
 
-func (e *nobidExchange) GetCache() prebid_cache_client.Client {
-	return nil
-}
-
 type brokenExchange struct{}
 
-func (e *brokenExchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, ids exchange.IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, debugLog string) (*openrtb.BidResponse, error) {
+func (e *brokenExchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, ids exchange.IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, debugLog *exchange.DebugLog) (*openrtb.BidResponse, error) {
 	return nil, errors.New("Critical, unrecoverable error.")
 }
 
-func (e *brokenExchange) GetCache() prebid_cache_client.Client {
-	return nil
-}
-
 func getMessage(t *testing.T, example []byte) []byte {
 	if value, err := jsonparser.GetString(example, "message"); err != nil {
 		t.Fatalf("Error parsing root.message from request: %v.", err)
@@ -1339,7 +1330,7 @@ type mockExchange struct {
 	lastRequest *openrtb.BidRequest
 }
 
-func (m *mockExchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, ids exchange.IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, debugLog string) (*openrtb.BidResponse, error) {
+func (m *mockExchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, ids exchange.IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, debugLog *exchange.DebugLog) (*openrtb.BidResponse, error) {
 	m.lastRequest = bidRequest
 	return &openrtb.BidResponse{
 		SeatBid: []openrtb.SeatBid{{
@@ -1350,10 +1341,6 @@ func (m *mockExchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidR
 	}, nil
 }
 
-func (m *mockExchange) GetCache() prebid_cache_client.Client {
-	return nil
-}
-
 func blankAdapterConfig(bidderList []openrtb_ext.BidderName, disabledBidders []string) map[string]config.Adapter {
 	adapters := make(map[string]config.Adapter)
 	for _, b := range bidderList {

endpoints/openrtb2/video_auction.go

@@ -32,14 +32,6 @@ import (
 
 var defaultRequestTimeout int64 = 5000
 
-type DebugLog struct {
-	enableDebug bool
-	data        string
-	ttl         int64
-	cacheType   prebid_cache_client.PayloadType
-	cacheKey    string
-}
-
 func NewVideoEndpoint(ex exchange.Exchange, validator openrtb_ext.BidderParamValidator, requestsById stored_requests.Fetcher, videoFetcher stored_requests.Fetcher, categories stored_requests.CategoryFetcher, cfg *config.Configuration, met pbsmetrics.MetricsEngine, pbsAnalytics analytics.PBSAnalyticsModule, disabledBidders map[string]string, defReqJSON []byte, bidderMap map[string]openrtb_ext.BidderName, cache prebid_cache_client.Client) (httprouter.Handle, error) {
 
 	if ex == nil || validator == nil || requestsById == nil || cfg == nil || met == nil {
@@ -95,29 +87,29 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re
 	if deps.cfg.CacheURL.DefaultTTLs.Video > 0 {
 		cacheTTL = int64(deps.cfg.CacheURL.DefaultTTLs.Video)
 	}
-	debugLog := DebugLog{
-		enableDebug: strings.EqualFold(debugQuery, "true"),
-		cacheType:   prebid_cache_client.TypeXML,
-		ttl:         cacheTTL,
+	debugLog := exchange.DebugLog{
+		EnableDebug: strings.EqualFold(debugQuery, "true"),
+		CacheType:   prebid_cache_client.TypeXML,
+		TTL:         cacheTTL,
 	}
 
 	defer func() {
-		if len(debugLog.cacheKey) > 0 && vo.VideoResponse == nil {
-			debugLog.data = fmt.Sprintf("<!--\n%s\n\nNo response created\n-->", debugLog.data)
-			data, err := json.Marshal(debugLog.data)
+		if len(debugLog.CacheKey) > 0 && vo.VideoResponse == nil {
+			debugLog.Data = fmt.Sprintf("<!--\n%s\n\nNo response created\n-->", debugLog.Data)
+			data, err := json.Marshal(debugLog.Data)
 			if err == nil {
 				toCache := []prebid_cache_client.Cacheable{
 					{
-						Type:       debugLog.cacheType,
+						Type:       debugLog.CacheType,
 						Data:       data,
-						TTLSeconds: debugLog.ttl,
-						Key:        "log_" + debugLog.cacheKey,
+						TTLSeconds: debugLog.TTL,
+						Key:        "log_" + debugLog.CacheKey,
 					},
 				}
 				if deps.cache != nil {
 					ctx := context.Background()
 					var cancel context.CancelFunc
-					ctx, cancel = context.WithDeadline(ctx, start.Add(time.Duration(defaultRequestTimeout)*time.Millisecond))
+					ctx, cancel = context.WithDeadline(ctx, start.Add(time.Duration(100)*time.Millisecond))
 					defer cancel()
 					deps.cache.PutJson(ctx, toCache)
 				}
@@ -139,10 +131,10 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re
 	}
 
 	resolvedRequest := requestJson
-	if debugLog.enableDebug {
-		debugLog.data = fmt.Sprintf("Request:\n%s", string(requestJson))
+	if debugLog.EnableDebug {
+		debugLog.Data = fmt.Sprintf("Request:\n%s", string(requestJson))
 		headerBytes, _ := json.Marshal(r.Header)
-		debugLog.data = fmt.Sprintf("%s\n\nHeaders:\n%s", debugLog.data, string(headerBytes))
+		debugLog.Data = fmt.Sprintf("%s\n\nHeaders:\n%s", debugLog.Data, string(headerBytes))
 	}
 
 	//load additional data - stored simplified req
@@ -188,7 +180,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re
 	//create full open rtb req from full video request
 	mergeData(videoBidReq, bidReq)
 	// If debug query param is set, force the response to enable test flag
-	if debugLog.enableDebug {
+	if debugLog.EnableDebug {
 		bidReq.Test = 1
 	}
 
@@ -252,7 +244,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re
 		return
 	}
 	//execute auction logic
-	response, err := deps.ex.HoldAuction(ctx, bidReq, usersyncs, labels, &deps.categories, debugLog.data)
+	response, err := deps.ex.HoldAuction(ctx, bidReq, usersyncs, labels, &deps.categories, &debugLog)
 	vo.Request = bidReq
 	vo.Response = response
 	if err != nil {
@@ -294,12 +286,12 @@ func cleanupVideoBidRequest(videoReq *openrtb_ext.BidRequestVideo, podErrors []P
 	return videoReq
 }
 
-func handleError(labels *pbsmetrics.Labels, w http.ResponseWriter, errL []error, vo *analytics.VideoObject, debugLog *DebugLog) {
-	if debugLog != nil && debugLog.enableDebug {
+func handleError(labels *pbsmetrics.Labels, w http.ResponseWriter, errL []error, vo *analytics.VideoObject, debugLog *exchange.DebugLog) {
+	if debugLog != nil && debugLog.EnableDebug {
 		if rawUUID, _ := uuid.NewV4(); len(rawUUID) > 0 {
-			debugLog.cacheKey = rawUUID.String()
+			debugLog.CacheKey = rawUUID.String()
 		}
-		errL = append(errL, fmt.Errorf("Debug cache ID: [%s]", debugLog.cacheKey))
+		errL = append(errL, fmt.Errorf("[Debug cache ID: %s]", debugLog.CacheKey))
 	}
 	labels.RequestStatus = pbsmetrics.RequestStatusErr
 	var errors string

endpoints/openrtb2/video_auction_test.go

@@ -172,6 +172,90 @@ func TestCreateBidExtensionExactDurTrueNoPriceRange(t *testing.T) {
 	assert.Equal(t, resExt.Prebid.Targeting.PriceGranularity, openrtb_ext.PriceGranularityFromString("med"), "Price granularity is incorrect")
 }
 
+func TestVideoEndpointDebugQueryTrue(t *testing.T) {
+	ex := &mockExchangeVideo{
+		cache: &mockCacheClient{},
+	}
+	reqData, err := ioutil.ReadFile("sample-requests/video/video_valid_sample.json")
+	if err != nil {
+		t.Fatalf("Failed to fetch a valid request: %v", err)
+	}
+	reqBody := string(getRequestPayload(t, reqData))
+	req := httptest.NewRequest("POST", "/openrtb2/video?debug=true", strings.NewReader(reqBody))
+	recorder := httptest.NewRecorder()
+
+	deps := mockDeps(t, ex)
+	deps.VideoAuctionEndpoint(recorder, req, nil)
+
+	if ex.lastRequest == nil {
+		t.Fatalf("The request never made it into the Exchange.")
+	}
+	if !ex.cache.called {
+		t.Fatalf("Cache was not called when it should have been")
+	}
+
+	respBytes := recorder.Body.Bytes()
+	resp := &openrtb_ext.BidResponseVideo{}
+	if err := json.Unmarshal(respBytes, resp); err != nil {
+		t.Fatalf("Unable to umarshal response.")
+	}
+
+	assert.Len(t, ex.lastRequest.Imp, 11, "Incorrect number of impressions in request")
+	assert.Equal(t, string(ex.lastRequest.Site.Page), "prebid.com", "Incorrect site page in request")
+	assert.Equal(t, ex.lastRequest.Site.Content.Series, "TvName", "Incorrect site content series in request")
+
+	assert.Len(t, resp.AdPods, 5, "Incorrect number of Ad Pods in response")
+	assert.Len(t, resp.AdPods[0].Targeting, 4, "Incorrect Targeting data in response")
+	assert.Len(t, resp.AdPods[1].Targeting, 3, "Incorrect Targeting data in response")
+	assert.Len(t, resp.AdPods[2].Targeting, 5, "Incorrect Targeting data in response")
+	assert.Len(t, resp.AdPods[3].Targeting, 1, "Incorrect Targeting data in response")
+	assert.Len(t, resp.AdPods[4].Targeting, 3, "Incorrect Targeting data in response")
+
+	assert.Equal(t, resp.AdPods[4].Targeting[0].HbPbCatDur, "20.00_395_30s", "Incorrect number of Ad Pods in response")
+}
+
+func TestVideoEndpointDebugQueryFalse(t *testing.T) {
+	ex := &mockExchangeVideo{
+		cache: &mockCacheClient{},
+	}
+	reqData, err := ioutil.ReadFile("sample-requests/video/video_valid_sample.json")
+	if err != nil {
+		t.Fatalf("Failed to fetch a valid request: %v", err)
+	}
+	reqBody := string(getRequestPayload(t, reqData))
+	req := httptest.NewRequest("POST", "/openrtb2/video?debug=123", strings.NewReader(reqBody))
+	recorder := httptest.NewRecorder()
+
+	deps := mockDeps(t, ex)
+	deps.VideoAuctionEndpoint(recorder, req, nil)
+
+	if ex.lastRequest == nil {
+		t.Fatalf("The request never made it into the Exchange.")
+	}
+	if ex.cache.called {
+		t.Fatalf("Cache was called when it shouldn't have been")
+	}
+
+	respBytes := recorder.Body.Bytes()
+	resp := &openrtb_ext.BidResponseVideo{}
+	if err := json.Unmarshal(respBytes, resp); err != nil {
+		t.Fatalf("Unable to umarshal response.")
+	}
+
+	assert.Len(t, ex.lastRequest.Imp, 11, "Incorrect number of impressions in request")
+	assert.Equal(t, string(ex.lastRequest.Site.Page), "prebid.com", "Incorrect site page in request")
+	assert.Equal(t, ex.lastRequest.Site.Content.Series, "TvName", "Incorrect site content series in request")
+
+	assert.Len(t, resp.AdPods, 5, "Incorrect number of Ad Pods in response")
+	assert.Len(t, resp.AdPods[0].Targeting, 4, "Incorrect Targeting data in response")
+	assert.Len(t, resp.AdPods[1].Targeting, 3, "Incorrect Targeting data in response")
+	assert.Len(t, resp.AdPods[2].Targeting, 5, "Incorrect Targeting data in response")
+	assert.Len(t, resp.AdPods[3].Targeting, 1, "Incorrect Targeting data in response")
+	assert.Len(t, resp.AdPods[4].Targeting, 3, "Incorrect Targeting data in response")
+
+	assert.Equal(t, resp.AdPods[4].Targeting[0].HbPbCatDur, "20.00_395_30s", "Incorrect number of Ad Pods in response")
+}
+
 func TestVideoEndpointNoPods(t *testing.T) {
 	ex := &mockExchangeVideo{}
 	reqData, err := ioutil.ReadFile("sample-requests/video/video_invalid_sample.json")
@@ -821,6 +905,41 @@ func TestParseVideoRequestWithoutUserAgentAndEmptyHeader(t *testing.T) {
 
 }
 
+func TestHandleErrorDebugLog(t *testing.T) {
+	vo := analytics.VideoObject{
+		Status: 200,
+		Errors: make([]error, 0),
+	}
+
+	labels := pbsmetrics.Labels{
+		Source:        pbsmetrics.DemandUnknown,
+		RType:         pbsmetrics.ReqTypeVideo,
+		PubID:         pbsmetrics.PublisherUnknown,
+		Browser:       "test browser",
+		CookieFlag:    pbsmetrics.CookieFlagUnknown,
+		RequestStatus: pbsmetrics.RequestStatusOK,
+	}
+
+	recorder := httptest.NewRecorder()
+	err1 := errors.New("Error for testing handleError 1")
+	err2 := errors.New("Error for testing handleError 2")
+	debugLog := exchange.DebugLog{
+		EnableDebug: true,
+		CacheType:   prebid_cache_client.TypeXML,
+		Data:        "test debug data",
+		TTL:         int64(3600),
+	}
+	handleError(&labels, recorder, []error{err1, err2}, &vo, &debugLog)
+
+	assert.Equal(t, pbsmetrics.RequestStatusErr, labels.RequestStatus, "labels.RequestStatus should indicate an error")
+	assert.Equal(t, 500, recorder.Code, "Error status should be written to writer")
+	assert.Equal(t, 500, vo.Status, "Analytics object should have error status")
+	assert.Equal(t, 3, len(vo.Errors), "New errors including debug cache ID should be appended to Analytics object Errors")
+	assert.Equal(t, "Error for testing handleError 1", vo.Errors[0].Error(), "Error in Analytics object should have test error message for first error")
+	assert.Equal(t, "Error for testing handleError 2", vo.Errors[1].Error(), "Error in Analytics object should have test error message for second error")
+	assert.NotEmpty(t, debugLog.CacheKey, "DebugLog CacheKey value should have been set")
+}
+
 func mockDepsWithMetrics(t *testing.T, ex *mockExchangeVideo) (*endpointDeps, *pbsmetrics.Metrics, *mockAnalyticsModule) {
 	theMetrics := pbsmetrics.NewMetrics(metrics.NewRegistry(), openrtb_ext.BidderList(), config.DisabledMetrics{})
 	mockModule := &mockAnalyticsModule{}
@@ -877,12 +996,24 @@ func mockDeps(t *testing.T, ex *mockExchangeVideo) *endpointDeps {
 		false,
 		[]byte{},
 		openrtb_ext.BidderMap,
-		nil,
+		ex.cache,
 	}
 
 	return edep
 }
 
+type mockCacheClient struct {
+	called bool
+}
+
+func (m *mockCacheClient) PutJson(ctx context.Context, values []prebid_cache_client.Cacheable) ([]string, []error) {
+	return []string{}, []error{}
+}
+
+func (m *mockCacheClient) GetExtCacheData() (string, string) {
+	return "", ""
+}
+
 type mockVideoStoredReqFetcher struct {
 }
 
@@ -892,10 +1023,14 @@ func (cf mockVideoStoredReqFetcher) FetchRequests(ctx context.Context, requestID
 
 type mockExchangeVideo struct {
 	lastRequest *openrtb.BidRequest
+	cache       *mockCacheClient
 }
 
-func (m *mockExchangeVideo) HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, ids exchange.IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, debugLog string) (*openrtb.BidResponse, error) {
+func (m *mockExchangeVideo) HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, ids exchange.IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, debugLog *exchange.DebugLog) (*openrtb.BidResponse, error) {
 	m.lastRequest = bidRequest
+	if debugLog != nil && debugLog.EnableDebug {
+		m.cache.called = true
+	}
 	ext := []byte(`{"prebid":{"targeting":{"hb_bidder":"appnexus","hb_pb":"20.00","hb_pb_cat_dur":"20.00_395_30s","hb_size":"1x1", "hb_uuid":"837ea3b7-5598-4958-8c45-8e9ef2bf7cc1"},"type":"video"},"bidder":{"appnexus":{"brand_id":1,"auction_id":7840037870526938650,"bidder_id":2,"bid_ad_type":1,"creative_info":{"video":{"duration":30,"mimes":["video\/mp4"]}}}}}`)
 	return &openrtb.BidResponse{
 		SeatBid: []openrtb.SeatBid{{
@@ -921,10 +1056,6 @@ func (m *mockExchangeVideo) HoldAuction(ctx context.Context, bidRequest *openrtb
 	}, nil
 }
 
-func (m *mockExchangeVideo) GetCache() prebid_cache_client.Client {
-	return nil
-}
-
 var testVideoStoredImpData = map[string]json.RawMessage{
 	"fba10607-0c12-43d1-ad07-b8a513bc75d6": json.RawMessage(`{"ext": {"appnexus": {"placementId": 14997137}}}`),
 	"8b452b41-2681-4a20-9086-6f16ffad7773": json.RawMessage(`{"ext": {"appnexus": {"placementId": 15016213}}}`),