From 1ac57de6899875f3ab301042c1aac1f17628132e Mon Sep 17 00:00:00 2001 From: Cameron Rice Date: Wed, 11 Mar 2020 20:18:38 -0700 Subject: [PATCH 1/8] WIP added logging to cache for video endpoint --- endpoints/openrtb2/amp_auction.go | 2 +- endpoints/openrtb2/amp_auction_test.go | 7 ++- endpoints/openrtb2/auction.go | 2 +- endpoints/openrtb2/auction_test.go | 19 ++++++-- endpoints/openrtb2/video_auction.go | 58 ++++++++++++++++++------ endpoints/openrtb2/video_auction_test.go | 9 +++- exchange/auction.go | 5 +- exchange/auction_test.go | 2 +- exchange/exchange.go | 17 +++++-- exchange/exchange_test.go | 6 +-- exchange/targeting_test.go | 2 +- 11 files changed, 98 insertions(+), 31 deletions(-) diff --git a/endpoints/openrtb2/amp_auction.go b/endpoints/openrtb2/amp_auction.go index d92f9d0ae61..815e6817ebb 100644 --- a/endpoints/openrtb2/amp_auction.go +++ b/endpoints/openrtb2/amp_auction.go @@ -165,7 +165,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, []byte{}) ao.AuctionResponse = response if err != nil { diff --git a/endpoints/openrtb2/amp_auction_test.go b/endpoints/openrtb2/amp_auction_test.go index c62a6a710d5..ffd76a4d70d 100644 --- a/endpoints/openrtb2/amp_auction_test.go +++ b/endpoints/openrtb2/amp_auction_test.go @@ -11,6 +11,7 @@ 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" @@ -902,7 +903,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) (*openrtb.BidResponse, error) { +func (m *mockAmpExchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, ids exchange.IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, videoReq []byte) (*openrtb.BidResponse, error) { m.lastRequest = bidRequest response := &openrtb.BidResponse{ @@ -926,6 +927,10 @@ 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 diff --git a/endpoints/openrtb2/auction.go b/endpoints/openrtb2/auction.go index a0ed19e5fa4..a44b3ff159b 100644 --- a/endpoints/openrtb2/auction.go +++ b/endpoints/openrtb2/auction.go @@ -137,7 +137,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, []byte{}) ao.Request = req ao.Response = response if err != nil { diff --git a/endpoints/openrtb2/auction_test.go b/endpoints/openrtb2/auction_test.go index 89f0fa255df..caa464b1f12 100644 --- a/endpoints/openrtb2/auction_test.go +++ b/endpoints/openrtb2/auction_test.go @@ -16,6 +16,7 @@ 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" @@ -953,7 +954,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) (*openrtb.BidResponse, error) { +func (e *nobidExchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, ids exchange.IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, videoReq []byte) (*openrtb.BidResponse, error) { e.gotRequest = bidRequest return &openrtb.BidResponse{ ID: bidRequest.ID, @@ -962,12 +963,20 @@ 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) (*openrtb.BidResponse, error) { +func (e *brokenExchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, ids exchange.IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, videoReq []byte) (*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) @@ -1324,7 +1333,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) (*openrtb.BidResponse, error) { +func (m *mockExchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, ids exchange.IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, videoReq []byte) (*openrtb.BidResponse, error) { m.lastRequest = bidRequest return &openrtb.BidResponse{ SeatBid: []openrtb.SeatBid{{ @@ -1335,6 +1344,10 @@ 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 { diff --git a/endpoints/openrtb2/video_auction.go b/endpoints/openrtb2/video_auction.go index 2a8663959a6..5662437d861 100644 --- a/endpoints/openrtb2/video_auction.go +++ b/endpoints/openrtb2/video_auction.go @@ -14,6 +14,7 @@ import ( "github.com/buger/jsonparser" jsonpatch "github.com/evanphx/json-patch" + "github.com/gofrs/uuid" "github.com/prebid/prebid-server/errortypes" "github.com/golang/glog" @@ -24,6 +25,7 @@ import ( "github.com/prebid/prebid-server/exchange" "github.com/prebid/prebid-server/openrtb_ext" "github.com/prebid/prebid-server/pbsmetrics" + "github.com/prebid/prebid-server/prebid_cache_client" "github.com/prebid/prebid-server/stored_requests" "github.com/prebid/prebid-server/usersync" ) @@ -79,7 +81,24 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re CookieFlag: pbsmetrics.CookieFlagUnknown, RequestStatus: pbsmetrics.RequestStatusOK, } + var videoReq []byte + debugQuery := r.URL.Query().Get("debug") + enableDebug := debugQuery == "true" + errorCacheID := "" defer func() { + if enableDebug && vo.VideoResponse == nil { + cache := deps.ex.GetCache() + data, _ := json.Marshal(string(videoReq)) + toCache := []prebid_cache_client.Cacheable{ + { + Type: prebid_cache_client.TypeXML, + Data: data, + TTLSeconds: int64(3600), + Key: errorCacheID, + }, + } + cache.PutJson(context.Background(), toCache) + } deps.metricsEngine.RecordRequest(labels) deps.metricsEngine.RecordRequestTime(labels, time.Since(start)) deps.analytics.LogVideoObject(&vo) @@ -91,38 +110,41 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re } requestJson, err := ioutil.ReadAll(lr) if err != nil { - handleError(&labels, w, []error{err}, &vo) + errorCacheID = handleError(&labels, w, []error{err}, &vo, enableDebug) return } resolvedRequest := requestJson + if enableDebug { + videoReq = requestJson + } //load additional data - stored simplified req storedRequestId, err := getVideoStoredRequestId(requestJson) if err != nil { if deps.cfg.VideoStoredRequestRequired { - handleError(&labels, w, []error{err}, &vo) + errorCacheID = handleError(&labels, w, []error{err}, &vo, enableDebug) return } } else { storedRequest, errs := deps.loadStoredVideoRequest(context.Background(), storedRequestId) if len(errs) > 0 { - handleError(&labels, w, errs, &vo) + errorCacheID = handleError(&labels, w, errs, &vo, enableDebug) return } //merge incoming req with stored video req resolvedRequest, err = jsonpatch.MergePatch(storedRequest, requestJson) if err != nil { - handleError(&labels, w, []error{err}, &vo) + errorCacheID = handleError(&labels, w, []error{err}, &vo, enableDebug) return } } //unmarshal and validate combined result videoBidReq, errL, podErrors := deps.parseVideoRequest(resolvedRequest, r.Header) if len(errL) > 0 { - handleError(&labels, w, errL, &vo) + errorCacheID = handleError(&labels, w, errL, &vo, enableDebug) return } @@ -132,7 +154,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re if deps.defaultRequest { if err := json.Unmarshal(deps.defReqJSON, bidReq); err != nil { err = fmt.Errorf("Invalid JSON in Default Request Settings: %s", err) - handleError(&labels, w, []error{err}, &vo) + errorCacheID = handleError(&labels, w, []error{err}, &vo, enableDebug) return } } @@ -156,7 +178,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re } err := errors.New(fmt.Sprintf("all pods are incorrect: %s", strings.Join(resPodErr, "; "))) errL = append(errL, err) - handleError(&labels, w, errL, &vo) + errorCacheID = handleError(&labels, w, errL, &vo, enableDebug) return } @@ -168,7 +190,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re errL = deps.validateRequest(bidReq) if len(errL) > 0 { - handleError(&labels, w, errL, &vo) + errorCacheID = handleError(&labels, w, errL, &vo, enableDebug) return } @@ -196,16 +218,16 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re if acctIdErr := validateAccount(deps.cfg, labels.PubID); acctIdErr != nil { errL = append(errL, acctIdErr) - handleError(&labels, w, errL, &vo) + errorCacheID = handleError(&labels, w, errL, &vo, enableDebug) return } //execute auction logic - response, err := deps.ex.HoldAuction(ctx, bidReq, usersyncs, labels, &deps.categories) + response, err := deps.ex.HoldAuction(ctx, bidReq, usersyncs, labels, &deps.categories, videoReq) vo.Request = bidReq vo.Response = response if err != nil { errL := []error{err} - handleError(&labels, w, errL, &vo) + errorCacheID = handleError(&labels, w, errL, &vo, enableDebug) return } @@ -213,7 +235,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re bidResp, err := buildVideoResponse(response, podErrors) if err != nil { errL := []error{err} - handleError(&labels, w, errL, &vo) + errorCacheID = handleError(&labels, w, errL, &vo, enableDebug) return } if bidReq.Test == 1 { @@ -226,7 +248,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re //resp, err := json.Marshal(response) if err != nil { errL := []error{err} - handleError(&labels, w, errL, &vo) + errorCacheID = handleError(&labels, w, errL, &vo, enableDebug) return } @@ -242,7 +264,14 @@ func cleanupVideoBidRequest(videoReq *openrtb_ext.BidRequestVideo, podErrors []P return videoReq } -func handleError(labels *pbsmetrics.Labels, w http.ResponseWriter, errL []error, vo *analytics.VideoObject) { +func handleError(labels *pbsmetrics.Labels, w http.ResponseWriter, errL []error, vo *analytics.VideoObject, enableDebug bool) string { + cacheID := "" + if enableDebug { + if rawUUID, _ := uuid.NewV4(); len(rawUUID) > 0 { + cacheID = rawUUID.String() + } + errL = append(errL, fmt.Errorf("Debug cache ID: [%s]", cacheID)) + } labels.RequestStatus = pbsmetrics.RequestStatusErr var errors string var status int = http.StatusInternalServerError @@ -264,6 +293,7 @@ func handleError(labels *pbsmetrics.Labels, w http.ResponseWriter, errL []error, fmt.Fprintf(w, "Critical error while running the video endpoint: %v", errors) glog.Errorf("/openrtb2/video Critical error: %v", errors) vo.Errors = append(vo.Errors, errL...) + return cacheID } func (deps *endpointDeps) createImpressions(videoReq *openrtb_ext.BidRequestVideo, podErrors []PodError) ([]openrtb.Imp, []PodError) { diff --git a/endpoints/openrtb2/video_auction_test.go b/endpoints/openrtb2/video_auction_test.go index a5ad62c9fa8..7090f58a092 100644 --- a/endpoints/openrtb2/video_auction_test.go +++ b/endpoints/openrtb2/video_auction_test.go @@ -17,6 +17,7 @@ import ( "github.com/prebid/prebid-server/exchange" "github.com/prebid/prebid-server/openrtb_ext" "github.com/prebid/prebid-server/pbsmetrics" + "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" metrics "github.com/rcrowley/go-metrics" @@ -714,7 +715,7 @@ func TestHandleError(t *testing.T) { recorder := httptest.NewRecorder() err1 := errors.New("Error for testing handleError 1") err2 := errors.New("Error for testing handleError 2") - handleError(&labels, recorder, []error{err1, err2}, &vo) + handleError(&labels, recorder, []error{err1, err2}, &vo, false) 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") @@ -891,7 +892,7 @@ type mockExchangeVideo struct { lastRequest *openrtb.BidRequest } -func (m *mockExchangeVideo) HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, ids exchange.IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher) (*openrtb.BidResponse, error) { +func (m *mockExchangeVideo) HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, ids exchange.IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, videoReq []byte) (*openrtb.BidResponse, error) { m.lastRequest = bidRequest 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{ @@ -918,6 +919,10 @@ 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}}}`), diff --git a/exchange/auction.go b/exchange/auction.go index 2b9a8cb58fc..c1622eb532e 100644 --- a/exchange/auction.go +++ b/exchange/auction.go @@ -60,7 +60,7 @@ func (a *auction) setRoundedPrices(priceGranularity openrtb_ext.PriceGranularity a.roundedPrices = roundedPrices } -func (a *auction) doCache(ctx context.Context, cache prebid_cache_client.Client, targData *targetData, bidRequest *openrtb.BidRequest, ttlBuffer int64, defaultTTLs *config.DefaultTTLs, bidCategory map[string]string) []error { +func (a *auction) doCache(ctx context.Context, cache prebid_cache_client.Client, targData *targetData, bidRequest *openrtb.BidRequest, ttlBuffer int64, defaultTTLs *config.DefaultTTLs, bidCategory map[string]string, videoDebug []byte) []error { var bids, vast, includeBidderKeys, includeWinners bool = targData.includeCacheBids, targData.includeCacheVast, targData.includeBidderKeys, targData.includeWinners if !((bids || vast) && (includeBidderKeys || includeWinners)) { return nil @@ -124,6 +124,9 @@ func (a *auction) doCache(ctx context.Context, cache prebid_cache_client.Client, } if vast && topBidPerBidder.bidType == openrtb_ext.BidTypeVideo { vast := makeVAST(topBidPerBidder.bid) + if len(videoDebug) > 0 { + vast = fmt.Sprintf("%s\n", vast, string(videoDebug)) + } if jsonBytes, err := json.Marshal(vast); err == nil { if useCustomCacheKey { toCache = append(toCache, prebid_cache_client.Cacheable{ diff --git a/exchange/auction_test.go b/exchange/auction_test.go index ea19732d82b..b0118276648 100644 --- a/exchange/auction_test.go +++ b/exchange/auction_test.go @@ -188,7 +188,7 @@ func runCacheSpec(t *testing.T, fileDisplayName string, specData *cacheSpec) { winningBidsByBidder: winningBidsByBidder, roundedPrices: roundedPrices, } - _ = testAuction.doCache(ctx, cache, targData, &specData.BidRequest, 60, &specData.DefaultTTLs, bidCategory) + _ = testAuction.doCache(ctx, cache, targData, &specData.BidRequest, 60, &specData.DefaultTTLs, bidCategory, []byte{}) if len(specData.ExpectedCacheables) > len(cache.items) { t.Errorf("%s: [CACHE_ERROR] Less elements were cached than expected \n", fileDisplayName) diff --git a/exchange/exchange.go b/exchange/exchange.go index ef10180a745..673ae57b390 100644 --- a/exchange/exchange.go +++ b/exchange/exchange.go @@ -30,7 +30,8 @@ import ( // Exchange runs Auctions. Implementations must be threadsafe, and will be shared across many goroutines. type Exchange interface { // HoldAuction executes an OpenRTB v2.5 Auction. - HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, usersyncs IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher) (*openrtb.BidResponse, error) + HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, usersyncs IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, videoReq []byte) (*openrtb.BidResponse, error) + GetCache() prebid_cache_client.Client } // IdFetcher can find the user's ID for a specific Bidder. @@ -78,7 +79,7 @@ func NewExchange(client *http.Client, cache prebid_cache_client.Client, cfg *con return e } -func (e *exchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, usersyncs IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher) (*openrtb.BidResponse, error) { +func (e *exchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, usersyncs IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, videoReq []byte) (*openrtb.BidResponse, error) { // Snapshot of resolved bid request for debug if test request resolvedRequest, err := buildResolvedRequest(bidRequest) if err != nil { @@ -162,7 +163,13 @@ func (e *exchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidReque if targData != nil { auc.setRoundedPrices(targData.priceGranularity) - cacheErrs := auc.doCache(ctx, e.cache, targData, bidRequest, 60, &e.defaultTTLs, bidCategory) + if len(videoReq) > 0 { + // Build the response so far + debugBidResp, _ := e.buildBidResponse(ctx, liveAdapters, adapterBids, bidRequest, resolvedRequest, adapterExtra, auc, errs) + bidRespBytes, _ := json.Marshal(debugBidResp) + videoReq = append(videoReq, bidRespBytes...) + } + cacheErrs := auc.doCache(ctx, e.cache, targData, bidRequest, 60, &e.defaultTTLs, bidCategory, videoReq) if len(cacheErrs) > 0 { errs = append(errs, cacheErrs...) } @@ -179,6 +186,10 @@ func (e *exchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidReque return e.buildBidResponse(ctx, liveAdapters, adapterBids, bidRequest, resolvedRequest, adapterExtra, auc, errs) } +func (e *exchange) GetCache() prebid_cache_client.Client { + return e.cache +} + type DealTierInfo struct { Prefix string `json:"prefix"` MinDealTier int `json:"minDealTier"` diff --git a/exchange/exchange_test.go b/exchange/exchange_test.go index 0a64bce0826..375337530af 100644 --- a/exchange/exchange_test.go +++ b/exchange/exchange_test.go @@ -489,7 +489,7 @@ func TestRaceIntegration(t *testing.T) { } theMetrics := pbsmetrics.NewMetrics(metrics.NewRegistry(), openrtb_ext.BidderList(), config.DisabledMetrics{}) ex := NewExchange(server.Client(), &wellBehavedCache{}, cfg, theMetrics, adapters.ParseBidderInfos(cfg.Adapters, "../static/bidder-info", openrtb_ext.BidderList()), gdpr.AlwaysAllow{}, currencies.NewRateConverterDefault()) - _, err := ex.HoldAuction(context.Background(), newRaceCheckingRequest(t), &emptyUsersync{}, pbsmetrics.Labels{}, &categoriesFetcher) + _, err := ex.HoldAuction(context.Background(), newRaceCheckingRequest(t), &emptyUsersync{}, pbsmetrics.Labels{}, &categoriesFetcher, []byte{}) if err != nil { t.Errorf("HoldAuction returned unexpected error: %v", err) } @@ -666,7 +666,7 @@ func TestPanicRecoveryHighLevel(t *testing.T) { if error != nil { t.Errorf("Failed to create a category Fetcher: %v", error) } - _, err := e.HoldAuction(context.Background(), request, &emptyUsersync{}, pbsmetrics.Labels{}, &categoriesFetcher) + _, err := e.HoldAuction(context.Background(), request, &emptyUsersync{}, pbsmetrics.Labels{}, &categoriesFetcher, []byte{}) if err != nil { t.Errorf("HoldAuction returned unexpected error: %v", err) } @@ -732,7 +732,7 @@ func runSpec(t *testing.T, filename string, spec *exchangeSpec) { if error != nil { t.Errorf("Failed to create a category Fetcher: %v", error) } - bid, err := ex.HoldAuction(context.Background(), &spec.IncomingRequest.OrtbRequest, mockIdFetcher(spec.IncomingRequest.Usersyncs), pbsmetrics.Labels{}, &categoriesFetcher) + bid, err := ex.HoldAuction(context.Background(), &spec.IncomingRequest.OrtbRequest, mockIdFetcher(spec.IncomingRequest.Usersyncs), pbsmetrics.Labels{}, &categoriesFetcher, []byte{}) responseTimes := extractResponseTimes(t, filename, bid) for _, bidderName := range biddersInAuction { if _, ok := responseTimes[bidderName]; !ok { diff --git a/exchange/targeting_test.go b/exchange/targeting_test.go index 92b338f97fb..95ba815ed0f 100644 --- a/exchange/targeting_test.go +++ b/exchange/targeting_test.go @@ -106,7 +106,7 @@ func runTargetingAuction(t *testing.T, mockBids map[openrtb_ext.BidderName][]*op if error != nil { t.Errorf("Failed to create a category Fetcher: %v", error) } - bidResp, err := ex.HoldAuction(context.Background(), req, &mockFetcher{}, pbsmetrics.Labels{}, &categoriesFetcher) + bidResp, err := ex.HoldAuction(context.Background(), req, &mockFetcher{}, pbsmetrics.Labels{}, &categoriesFetcher, []byte{}) if err != nil { t.Fatalf("Unexpected errors running auction: %v", err) From a678b505f1ef816022fe970419206de36e46c6ac Mon Sep 17 00:00:00 2001 From: Cameron Rice Date: Thu, 12 Mar 2020 10:12:34 -0700 Subject: [PATCH 2/8] Updating cache call to use TTL from config --- endpoints/openrtb2/video_auction.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/endpoints/openrtb2/video_auction.go b/endpoints/openrtb2/video_auction.go index 5662437d861..9d216eedac9 100644 --- a/endpoints/openrtb2/video_auction.go +++ b/endpoints/openrtb2/video_auction.go @@ -93,7 +93,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re { Type: prebid_cache_client.TypeXML, Data: data, - TTLSeconds: int64(3600), + TTLSeconds: int64(deps.cfg.CacheURL.DefaultTTLs.Video), Key: errorCacheID, }, } From 1f7a0aaf54d683a184a14812282cfe1c3b865eaa Mon Sep 17 00:00:00 2001 From: Cameron Rice Date: Thu, 12 Mar 2020 16:05:17 -0700 Subject: [PATCH 3/8] Updates from initial feedback * Log now includes HTTP headers * Fixed caching to use a new cache entry rather than appending to the VAST * Added feature where is query is set, the test flag is set in the request --- endpoints/openrtb2/amp_auction.go | 2 +- endpoints/openrtb2/amp_auction_test.go | 2 +- endpoints/openrtb2/auction.go | 2 +- endpoints/openrtb2/auction_test.go | 6 +++--- endpoints/openrtb2/video_auction.go | 19 ++++++++++++++----- endpoints/openrtb2/video_auction_test.go | 2 +- exchange/auction.go | 16 ++++++++++++---- exchange/auction_test.go | 2 +- exchange/exchange.go | 17 ++++++++++++----- exchange/exchange_test.go | 6 +++--- exchange/targeting_test.go | 2 +- 11 files changed, 50 insertions(+), 26 deletions(-) diff --git a/endpoints/openrtb2/amp_auction.go b/endpoints/openrtb2/amp_auction.go index 815e6817ebb..d5dd788863d 100644 --- a/endpoints/openrtb2/amp_auction.go +++ b/endpoints/openrtb2/amp_auction.go @@ -165,7 +165,7 @@ func (deps *endpointDeps) AmpAuction(w http.ResponseWriter, r *http.Request, _ h return } - response, err := deps.ex.HoldAuction(ctx, req, usersyncs, labels, &deps.categories, []byte{}) + response, err := deps.ex.HoldAuction(ctx, req, usersyncs, labels, &deps.categories, "") ao.AuctionResponse = response if err != nil { diff --git a/endpoints/openrtb2/amp_auction_test.go b/endpoints/openrtb2/amp_auction_test.go index ffd76a4d70d..45617b5ccef 100644 --- a/endpoints/openrtb2/amp_auction_test.go +++ b/endpoints/openrtb2/amp_auction_test.go @@ -903,7 +903,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, videoReq []byte) (*openrtb.BidResponse, error) { +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) { m.lastRequest = bidRequest response := &openrtb.BidResponse{ diff --git a/endpoints/openrtb2/auction.go b/endpoints/openrtb2/auction.go index a44b3ff159b..61082affb91 100644 --- a/endpoints/openrtb2/auction.go +++ b/endpoints/openrtb2/auction.go @@ -137,7 +137,7 @@ func (deps *endpointDeps) Auction(w http.ResponseWriter, r *http.Request, _ http return } - response, err := deps.ex.HoldAuction(ctx, req, usersyncs, labels, &deps.categories, []byte{}) + response, err := deps.ex.HoldAuction(ctx, req, usersyncs, labels, &deps.categories, "") ao.Request = req ao.Response = response if err != nil { diff --git a/endpoints/openrtb2/auction_test.go b/endpoints/openrtb2/auction_test.go index caa464b1f12..899f1a7decb 100644 --- a/endpoints/openrtb2/auction_test.go +++ b/endpoints/openrtb2/auction_test.go @@ -954,7 +954,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, videoReq []byte) (*openrtb.BidResponse, error) { +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) { e.gotRequest = bidRequest return &openrtb.BidResponse{ ID: bidRequest.ID, @@ -969,7 +969,7 @@ func (e *nobidExchange) GetCache() prebid_cache_client.Client { type brokenExchange struct{} -func (e *brokenExchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, ids exchange.IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, videoReq []byte) (*openrtb.BidResponse, error) { +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) { return nil, errors.New("Critical, unrecoverable error.") } @@ -1333,7 +1333,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, videoReq []byte) (*openrtb.BidResponse, error) { +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) { m.lastRequest = bidRequest return &openrtb.BidResponse{ SeatBid: []openrtb.SeatBid{{ diff --git a/endpoints/openrtb2/video_auction.go b/endpoints/openrtb2/video_auction.go index 9d216eedac9..b608a020088 100644 --- a/endpoints/openrtb2/video_auction.go +++ b/endpoints/openrtb2/video_auction.go @@ -81,20 +81,23 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re CookieFlag: pbsmetrics.CookieFlagUnknown, RequestStatus: pbsmetrics.RequestStatusOK, } - var videoReq []byte + debugQuery := r.URL.Query().Get("debug") enableDebug := debugQuery == "true" + debugString := "" errorCacheID := "" + defer func() { if enableDebug && vo.VideoResponse == nil { cache := deps.ex.GetCache() - data, _ := json.Marshal(string(videoReq)) + debugString = fmt.Sprintf("", debugString) + data, _ := json.Marshal(debugString) toCache := []prebid_cache_client.Cacheable{ { Type: prebid_cache_client.TypeXML, Data: data, TTLSeconds: int64(deps.cfg.CacheURL.DefaultTTLs.Video), - Key: errorCacheID, + Key: fmt.Sprintf("log_%s", errorCacheID), }, } cache.PutJson(context.Background(), toCache) @@ -116,7 +119,9 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re resolvedRequest := requestJson if enableDebug { - videoReq = requestJson + debugString = fmt.Sprintf("Request:\n%s", string(requestJson)) + headerBytes, _ := json.Marshal(r.Header) + debugString = fmt.Sprintf("%s\n\nHeaders:\n%s", debugString, string(headerBytes)) } //load additional data - stored simplified req @@ -161,6 +166,10 @@ 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 enableDebug { + bidReq.Test = 1 + } initialPodNumber := len(videoBidReq.PodConfig.Pods) if len(podErrors) > 0 { @@ -222,7 +231,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, videoReq) + response, err := deps.ex.HoldAuction(ctx, bidReq, usersyncs, labels, &deps.categories, debugString) vo.Request = bidReq vo.Response = response if err != nil { diff --git a/endpoints/openrtb2/video_auction_test.go b/endpoints/openrtb2/video_auction_test.go index 7090f58a092..2610103fef6 100644 --- a/endpoints/openrtb2/video_auction_test.go +++ b/endpoints/openrtb2/video_auction_test.go @@ -892,7 +892,7 @@ type mockExchangeVideo struct { lastRequest *openrtb.BidRequest } -func (m *mockExchangeVideo) HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, ids exchange.IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, videoReq []byte) (*openrtb.BidResponse, error) { +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) { m.lastRequest = bidRequest 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{ diff --git a/exchange/auction.go b/exchange/auction.go index c1622eb532e..9a21b2e36a9 100644 --- a/exchange/auction.go +++ b/exchange/auction.go @@ -60,7 +60,7 @@ func (a *auction) setRoundedPrices(priceGranularity openrtb_ext.PriceGranularity a.roundedPrices = roundedPrices } -func (a *auction) doCache(ctx context.Context, cache prebid_cache_client.Client, targData *targetData, bidRequest *openrtb.BidRequest, ttlBuffer int64, defaultTTLs *config.DefaultTTLs, bidCategory map[string]string, videoDebug []byte) []error { +func (a *auction) doCache(ctx context.Context, cache prebid_cache_client.Client, targData *targetData, bidRequest *openrtb.BidRequest, ttlBuffer int64, defaultTTLs *config.DefaultTTLs, bidCategory map[string]string, debugLog string) []error { var bids, vast, includeBidderKeys, includeWinners bool = targData.includeCacheBids, targData.includeCacheVast, targData.includeBidderKeys, targData.includeWinners if !((bids || vast) && (includeBidderKeys || includeWinners)) { return nil @@ -124,9 +124,6 @@ func (a *auction) doCache(ctx context.Context, cache prebid_cache_client.Client, } if vast && topBidPerBidder.bidType == openrtb_ext.BidTypeVideo { vast := makeVAST(topBidPerBidder.bid) - if len(videoDebug) > 0 { - vast = fmt.Sprintf("%s\n", vast, string(videoDebug)) - } if jsonBytes, err := json.Marshal(vast); err == nil { if useCustomCacheKey { toCache = append(toCache, prebid_cache_client.Cacheable{ @@ -150,6 +147,17 @@ func (a *auction) doCache(ctx context.Context, cache prebid_cache_client.Client, } } + if len(debugLog) > 0 { + if jsonBytes, err := json.Marshal(debugLog); err == nil { + toCache = append(toCache, prebid_cache_client.Cacheable{ + Type: prebid_cache_client.TypeXML, + Data: jsonBytes, + TTLSeconds: defTTL(openrtb_ext.BidTypeVideo, defaultTTLs), + Key: fmt.Sprintf("log_%s", hbCacheID), + }) + } + } + ids, err := cache.PutJson(ctx, toCache) if err != nil { errs = append(errs, err...) diff --git a/exchange/auction_test.go b/exchange/auction_test.go index b0118276648..705f17f1f2f 100644 --- a/exchange/auction_test.go +++ b/exchange/auction_test.go @@ -188,7 +188,7 @@ func runCacheSpec(t *testing.T, fileDisplayName string, specData *cacheSpec) { winningBidsByBidder: winningBidsByBidder, roundedPrices: roundedPrices, } - _ = testAuction.doCache(ctx, cache, targData, &specData.BidRequest, 60, &specData.DefaultTTLs, bidCategory, []byte{}) + _ = testAuction.doCache(ctx, cache, targData, &specData.BidRequest, 60, &specData.DefaultTTLs, bidCategory, "") if len(specData.ExpectedCacheables) > len(cache.items) { t.Errorf("%s: [CACHE_ERROR] Less elements were cached than expected \n", fileDisplayName) diff --git a/exchange/exchange.go b/exchange/exchange.go index 673ae57b390..eba39b09efb 100644 --- a/exchange/exchange.go +++ b/exchange/exchange.go @@ -30,7 +30,7 @@ import ( // Exchange runs Auctions. Implementations must be threadsafe, and will be shared across many goroutines. type Exchange interface { // HoldAuction executes an OpenRTB v2.5 Auction. - HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, usersyncs IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, videoReq []byte) (*openrtb.BidResponse, error) + HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, usersyncs IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, debugLog string) (*openrtb.BidResponse, error) GetCache() prebid_cache_client.Client } @@ -79,7 +79,7 @@ func NewExchange(client *http.Client, cache prebid_cache_client.Client, cfg *con return e } -func (e *exchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, usersyncs IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, videoReq []byte) (*openrtb.BidResponse, error) { +func (e *exchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, usersyncs IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, debugLog string) (*openrtb.BidResponse, error) { // Snapshot of resolved bid request for debug if test request resolvedRequest, err := buildResolvedRequest(bidRequest) if err != nil { @@ -163,13 +163,20 @@ func (e *exchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidReque if targData != nil { auc.setRoundedPrices(targData.priceGranularity) - if len(videoReq) > 0 { + if len(debugLog) > 0 { // Build the response so far debugBidResp, _ := e.buildBidResponse(ctx, liveAdapters, adapterBids, bidRequest, resolvedRequest, adapterExtra, auc, errs) + + // Remove the resolved request due to including duplicate info + var respExt openrtb_ext.ExtBidResponse + json.Unmarshal(debugBidResp.Ext, &respExt) + respExt.Debug.ResolvedRequest = nil + debugBidResp.Ext, _ = json.Marshal(respExt) + bidRespBytes, _ := json.Marshal(debugBidResp) - videoReq = append(videoReq, bidRespBytes...) + debugLog = fmt.Sprintf("", debugLog, string(bidRespBytes)) } - cacheErrs := auc.doCache(ctx, e.cache, targData, bidRequest, 60, &e.defaultTTLs, bidCategory, videoReq) + cacheErrs := auc.doCache(ctx, e.cache, targData, bidRequest, 60, &e.defaultTTLs, bidCategory, debugLog) if len(cacheErrs) > 0 { errs = append(errs, cacheErrs...) } diff --git a/exchange/exchange_test.go b/exchange/exchange_test.go index 375337530af..f5bfe2f5a50 100644 --- a/exchange/exchange_test.go +++ b/exchange/exchange_test.go @@ -489,7 +489,7 @@ func TestRaceIntegration(t *testing.T) { } theMetrics := pbsmetrics.NewMetrics(metrics.NewRegistry(), openrtb_ext.BidderList(), config.DisabledMetrics{}) ex := NewExchange(server.Client(), &wellBehavedCache{}, cfg, theMetrics, adapters.ParseBidderInfos(cfg.Adapters, "../static/bidder-info", openrtb_ext.BidderList()), gdpr.AlwaysAllow{}, currencies.NewRateConverterDefault()) - _, err := ex.HoldAuction(context.Background(), newRaceCheckingRequest(t), &emptyUsersync{}, pbsmetrics.Labels{}, &categoriesFetcher, []byte{}) + _, err := ex.HoldAuction(context.Background(), newRaceCheckingRequest(t), &emptyUsersync{}, pbsmetrics.Labels{}, &categoriesFetcher, "") if err != nil { t.Errorf("HoldAuction returned unexpected error: %v", err) } @@ -666,7 +666,7 @@ func TestPanicRecoveryHighLevel(t *testing.T) { if error != nil { t.Errorf("Failed to create a category Fetcher: %v", error) } - _, err := e.HoldAuction(context.Background(), request, &emptyUsersync{}, pbsmetrics.Labels{}, &categoriesFetcher, []byte{}) + _, err := e.HoldAuction(context.Background(), request, &emptyUsersync{}, pbsmetrics.Labels{}, &categoriesFetcher, "") if err != nil { t.Errorf("HoldAuction returned unexpected error: %v", err) } @@ -732,7 +732,7 @@ func runSpec(t *testing.T, filename string, spec *exchangeSpec) { if error != nil { t.Errorf("Failed to create a category Fetcher: %v", error) } - bid, err := ex.HoldAuction(context.Background(), &spec.IncomingRequest.OrtbRequest, mockIdFetcher(spec.IncomingRequest.Usersyncs), pbsmetrics.Labels{}, &categoriesFetcher, []byte{}) + bid, err := ex.HoldAuction(context.Background(), &spec.IncomingRequest.OrtbRequest, mockIdFetcher(spec.IncomingRequest.Usersyncs), pbsmetrics.Labels{}, &categoriesFetcher, "") responseTimes := extractResponseTimes(t, filename, bid) for _, bidderName := range biddersInAuction { if _, ok := responseTimes[bidderName]; !ok { diff --git a/exchange/targeting_test.go b/exchange/targeting_test.go index 95ba815ed0f..7e97080fc0d 100644 --- a/exchange/targeting_test.go +++ b/exchange/targeting_test.go @@ -106,7 +106,7 @@ func runTargetingAuction(t *testing.T, mockBids map[openrtb_ext.BidderName][]*op if error != nil { t.Errorf("Failed to create a category Fetcher: %v", error) } - bidResp, err := ex.HoldAuction(context.Background(), req, &mockFetcher{}, pbsmetrics.Labels{}, &categoriesFetcher, []byte{}) + bidResp, err := ex.HoldAuction(context.Background(), req, &mockFetcher{}, pbsmetrics.Labels{}, &categoriesFetcher, "") if err != nil { t.Fatalf("Unexpected errors running auction: %v", err) From c60768c76be2adb87b3cfa215d0c2f30b9a13420 Mon Sep 17 00:00:00 2001 From: Cameron Rice Date: Thu, 12 Mar 2020 19:14:37 -0700 Subject: [PATCH 4/8] Updated recorded response and handleError --- endpoints/openrtb2/video_auction.go | 40 +++++++++++------------- endpoints/openrtb2/video_auction_test.go | 3 +- exchange/exchange.go | 7 +++++ 3 files changed, 28 insertions(+), 22 deletions(-) diff --git a/endpoints/openrtb2/video_auction.go b/endpoints/openrtb2/video_auction.go index b608a020088..c6cfbde9c6e 100644 --- a/endpoints/openrtb2/video_auction.go +++ b/endpoints/openrtb2/video_auction.go @@ -84,13 +84,13 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re debugQuery := r.URL.Query().Get("debug") enableDebug := debugQuery == "true" - debugString := "" - errorCacheID := "" + var debugString string + var errorCacheID string defer func() { - if enableDebug && vo.VideoResponse == nil { + if len(errorCacheID) > 0 && vo.VideoResponse == nil { cache := deps.ex.GetCache() - debugString = fmt.Sprintf("", debugString) + debugString = fmt.Sprintf("", debugString) data, _ := json.Marshal(debugString) toCache := []prebid_cache_client.Cacheable{ { @@ -113,7 +113,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re } requestJson, err := ioutil.ReadAll(lr) if err != nil { - errorCacheID = handleError(&labels, w, []error{err}, &vo, enableDebug) + handleError(&labels, w, []error{err}, &vo, enableDebug, &errorCacheID) return } @@ -129,27 +129,27 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re if err != nil { if deps.cfg.VideoStoredRequestRequired { - errorCacheID = handleError(&labels, w, []error{err}, &vo, enableDebug) + handleError(&labels, w, []error{err}, &vo, enableDebug, &errorCacheID) return } } else { storedRequest, errs := deps.loadStoredVideoRequest(context.Background(), storedRequestId) if len(errs) > 0 { - errorCacheID = handleError(&labels, w, errs, &vo, enableDebug) + handleError(&labels, w, errs, &vo, enableDebug, &errorCacheID) return } //merge incoming req with stored video req resolvedRequest, err = jsonpatch.MergePatch(storedRequest, requestJson) if err != nil { - errorCacheID = handleError(&labels, w, []error{err}, &vo, enableDebug) + handleError(&labels, w, []error{err}, &vo, enableDebug, &errorCacheID) return } } //unmarshal and validate combined result videoBidReq, errL, podErrors := deps.parseVideoRequest(resolvedRequest, r.Header) if len(errL) > 0 { - errorCacheID = handleError(&labels, w, errL, &vo, enableDebug) + handleError(&labels, w, errL, &vo, enableDebug, &errorCacheID) return } @@ -159,7 +159,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re if deps.defaultRequest { if err := json.Unmarshal(deps.defReqJSON, bidReq); err != nil { err = fmt.Errorf("Invalid JSON in Default Request Settings: %s", err) - errorCacheID = handleError(&labels, w, []error{err}, &vo, enableDebug) + handleError(&labels, w, []error{err}, &vo, enableDebug, &errorCacheID) return } } @@ -187,7 +187,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re } err := errors.New(fmt.Sprintf("all pods are incorrect: %s", strings.Join(resPodErr, "; "))) errL = append(errL, err) - errorCacheID = handleError(&labels, w, errL, &vo, enableDebug) + handleError(&labels, w, errL, &vo, enableDebug, &errorCacheID) return } @@ -199,7 +199,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re errL = deps.validateRequest(bidReq) if len(errL) > 0 { - errorCacheID = handleError(&labels, w, errL, &vo, enableDebug) + handleError(&labels, w, errL, &vo, enableDebug, &errorCacheID) return } @@ -227,7 +227,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re if acctIdErr := validateAccount(deps.cfg, labels.PubID); acctIdErr != nil { errL = append(errL, acctIdErr) - errorCacheID = handleError(&labels, w, errL, &vo, enableDebug) + handleError(&labels, w, errL, &vo, enableDebug, &errorCacheID) return } //execute auction logic @@ -236,7 +236,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re vo.Response = response if err != nil { errL := []error{err} - errorCacheID = handleError(&labels, w, errL, &vo, enableDebug) + handleError(&labels, w, errL, &vo, enableDebug, &errorCacheID) return } @@ -244,7 +244,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re bidResp, err := buildVideoResponse(response, podErrors) if err != nil { errL := []error{err} - errorCacheID = handleError(&labels, w, errL, &vo, enableDebug) + handleError(&labels, w, errL, &vo, enableDebug, &errorCacheID) return } if bidReq.Test == 1 { @@ -257,7 +257,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re //resp, err := json.Marshal(response) if err != nil { errL := []error{err} - errorCacheID = handleError(&labels, w, errL, &vo, enableDebug) + handleError(&labels, w, errL, &vo, enableDebug, &errorCacheID) return } @@ -273,13 +273,12 @@ func cleanupVideoBidRequest(videoReq *openrtb_ext.BidRequestVideo, podErrors []P return videoReq } -func handleError(labels *pbsmetrics.Labels, w http.ResponseWriter, errL []error, vo *analytics.VideoObject, enableDebug bool) string { - cacheID := "" +func handleError(labels *pbsmetrics.Labels, w http.ResponseWriter, errL []error, vo *analytics.VideoObject, enableDebug bool, errorCacheID *string) { if enableDebug { if rawUUID, _ := uuid.NewV4(); len(rawUUID) > 0 { - cacheID = rawUUID.String() + *errorCacheID = rawUUID.String() } - errL = append(errL, fmt.Errorf("Debug cache ID: [%s]", cacheID)) + errL = append(errL, fmt.Errorf("Debug cache ID: [%s]", *errorCacheID)) } labels.RequestStatus = pbsmetrics.RequestStatusErr var errors string @@ -302,7 +301,6 @@ func handleError(labels *pbsmetrics.Labels, w http.ResponseWriter, errL []error, fmt.Fprintf(w, "Critical error while running the video endpoint: %v", errors) glog.Errorf("/openrtb2/video Critical error: %v", errors) vo.Errors = append(vo.Errors, errL...) - return cacheID } func (deps *endpointDeps) createImpressions(videoReq *openrtb_ext.BidRequestVideo, podErrors []PodError) ([]openrtb.Imp, []PodError) { diff --git a/endpoints/openrtb2/video_auction_test.go b/endpoints/openrtb2/video_auction_test.go index 2610103fef6..fe4e8ed81a4 100644 --- a/endpoints/openrtb2/video_auction_test.go +++ b/endpoints/openrtb2/video_auction_test.go @@ -715,7 +715,8 @@ func TestHandleError(t *testing.T) { recorder := httptest.NewRecorder() err1 := errors.New("Error for testing handleError 1") err2 := errors.New("Error for testing handleError 2") - handleError(&labels, recorder, []error{err1, err2}, &vo, false) + errorCacheID := "" + handleError(&labels, recorder, []error{err1, err2}, &vo, false, &errorCacheID) 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") diff --git a/exchange/exchange.go b/exchange/exchange.go index eba39b09efb..f9cb94a394f 100644 --- a/exchange/exchange.go +++ b/exchange/exchange.go @@ -167,6 +167,13 @@ func (e *exchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidReque // Build the response so far debugBidResp, _ := e.buildBidResponse(ctx, liveAdapters, adapterBids, bidRequest, resolvedRequest, adapterExtra, auc, errs) + // Remove the VAST object from the request + for i := 0; i < len(debugBidResp.SeatBid); i++ { + for j := 0; j < len(debugBidResp.SeatBid[i].Bid); j++ { + debugBidResp.SeatBid[i].Bid[j].AdM = "" + } + } + // Remove the resolved request due to including duplicate info var respExt openrtb_ext.ExtBidResponse json.Unmarshal(debugBidResp.Ext, &respExt) From e939e3d74d0f5478e128da60104fb5260e1da6e6 Mon Sep 17 00:00:00 2001 From: Cameron Rice Date: Fri, 13 Mar 2020 20:41:28 -0700 Subject: [PATCH 5/8] Updates from code review comments * Changed recorded output to be only the debug ext * Removed extra marhal calls * Changed cache to be an endpoint dependency * Added debugLog struct to hold all debug related info * Numerous smaller changes --- endpoints/openrtb2/amp_auction.go | 3 +- endpoints/openrtb2/auction.go | 5 +- endpoints/openrtb2/auction_test.go | 8 +- endpoints/openrtb2/video_auction.go | 97 ++++++++++++++---------- endpoints/openrtb2/video_auction_test.go | 5 +- exchange/exchange.go | 35 +++------ exchange/exchange_test.go | 6 +- router/router.go | 2 +- 8 files changed, 88 insertions(+), 73 deletions(-) diff --git a/endpoints/openrtb2/amp_auction.go b/endpoints/openrtb2/amp_auction.go index d5dd788863d..ede666cf90f 100644 --- a/endpoints/openrtb2/amp_auction.go +++ b/endpoints/openrtb2/amp_auction.go @@ -71,7 +71,8 @@ func NewAmpEndpoint( disabledBidders, defRequest, defReqJSON, - bidderMap}).AmpAuction), nil + bidderMap, + nil}).AmpAuction), nil } diff --git a/endpoints/openrtb2/auction.go b/endpoints/openrtb2/auction.go index 61082affb91..1050a89f99e 100644 --- a/endpoints/openrtb2/auction.go +++ b/endpoints/openrtb2/auction.go @@ -27,6 +27,7 @@ import ( "github.com/prebid/prebid-server/openrtb_ext" "github.com/prebid/prebid-server/pbsmetrics" "github.com/prebid/prebid-server/prebid" + "github.com/prebid/prebid-server/prebid_cache_client" "github.com/prebid/prebid-server/privacy/ccpa" "github.com/prebid/prebid-server/stored_requests" "github.com/prebid/prebid-server/stored_requests/backends/empty_fetcher" @@ -55,7 +56,8 @@ func NewEndpoint(ex exchange.Exchange, validator openrtb_ext.BidderParamValidato disabledBidders, defRequest, defReqJSON, - bidderMap}).Auction), nil + bidderMap, + nil}).Auction), nil } type endpointDeps struct { @@ -71,6 +73,7 @@ type endpointDeps struct { defaultRequest bool defReqJSON []byte bidderMap map[string]openrtb_ext.BidderName + cache prebid_cache_client.Client } func (deps *endpointDeps) Auction(w http.ResponseWriter, r *http.Request, _ httprouter.Params) { diff --git a/endpoints/openrtb2/auction_test.go b/endpoints/openrtb2/auction_test.go index 899f1a7decb..8e9c12e9f16 100644 --- a/endpoints/openrtb2/auction_test.go +++ b/endpoints/openrtb2/auction_test.go @@ -603,7 +603,7 @@ func TestStoredRequests(t *testing.T) { // NewMetrics() will create a new go_metrics MetricsEngine, bypassing the need for a crafted configuration set to support it. // As a side effect this gives us some coverage of the go_metrics piece of the metrics engine. theMetrics := pbsmetrics.NewMetrics(metrics.NewRegistry(), openrtb_ext.BidderList(), config.DisabledMetrics{}) - edep := &endpointDeps{&nobidExchange{}, newParamsValidator(t), &mockStoredReqFetcher{}, empty_fetcher.EmptyFetcher{}, empty_fetcher.EmptyFetcher{}, &config.Configuration{MaxRequestSize: maxSize}, theMetrics, analyticsConf.NewPBSAnalytics(&config.Analytics{}), map[string]string{}, false, []byte{}, openrtb_ext.BidderMap} + edep := &endpointDeps{&nobidExchange{}, newParamsValidator(t), &mockStoredReqFetcher{}, empty_fetcher.EmptyFetcher{}, empty_fetcher.EmptyFetcher{}, &config.Configuration{MaxRequestSize: maxSize}, theMetrics, analyticsConf.NewPBSAnalytics(&config.Analytics{}), map[string]string{}, false, []byte{}, openrtb_ext.BidderMap, nil} for i, requestData := range testStoredRequests { newRequest, errList := edep.processStoredRequests(context.Background(), json.RawMessage(requestData)) @@ -639,6 +639,7 @@ func TestOversizedRequest(t *testing.T) { false, []byte{}, openrtb_ext.BidderMap, + nil, } req := httptest.NewRequest("POST", "/openrtb2/auction", strings.NewReader(reqBody)) @@ -671,6 +672,7 @@ func TestRequestSizeEdgeCase(t *testing.T) { false, []byte{}, openrtb_ext.BidderMap, + nil, } req := httptest.NewRequest("POST", "/openrtb2/auction", strings.NewReader(reqBody)) @@ -808,6 +810,7 @@ func TestDisabledBidder(t *testing.T) { false, []byte{}, openrtb_ext.BidderMap, + nil, } req := httptest.NewRequest("POST", "/openrtb2/auction", strings.NewReader(reqBody)) @@ -841,6 +844,7 @@ func TestValidateImpExtDisabledBidder(t *testing.T) { false, []byte{}, openrtb_ext.BidderMap, + nil, } errs := deps.validateImpExt(imp, nil, 0) assert.JSONEq(t, `{"appnexus":{"placement_id":555}}`, string(imp.Ext)) @@ -879,6 +883,7 @@ func TestCurrencyTrunc(t *testing.T) { false, []byte{}, openrtb_ext.BidderMap, + nil, } ui := uint64(1) @@ -920,6 +925,7 @@ func TestCCPAInvalidValueWarning(t *testing.T) { false, []byte{}, openrtb_ext.BidderMap, + nil, } ui := uint64(1) diff --git a/endpoints/openrtb2/video_auction.go b/endpoints/openrtb2/video_auction.go index c6cfbde9c6e..4791bbf7608 100644 --- a/endpoints/openrtb2/video_auction.go +++ b/endpoints/openrtb2/video_auction.go @@ -32,14 +32,22 @@ import ( var defaultRequestTimeout int64 = 5000 -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) (httprouter.Handle, error) { +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 { return nil, errors.New("NewVideoEndpoint requires non-nil arguments.") } defRequest := defReqJSON != nil && len(defReqJSON) > 0 - return httprouter.Handle((&endpointDeps{ex, validator, requestsById, videoFetcher, categories, cfg, met, pbsAnalytics, disabledBidders, defRequest, defReqJSON, bidderMap}).VideoAuctionEndpoint), nil + return httprouter.Handle((&endpointDeps{ex, validator, requestsById, videoFetcher, categories, cfg, met, pbsAnalytics, disabledBidders, defRequest, defReqJSON, bidderMap, cache}).VideoAuctionEndpoint), nil } /* @@ -83,24 +91,37 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re } debugQuery := r.URL.Query().Get("debug") - enableDebug := debugQuery == "true" - var debugString string - var errorCacheID string + cacheTTL := int64(3600) + 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, + } defer func() { - if len(errorCacheID) > 0 && vo.VideoResponse == nil { - cache := deps.ex.GetCache() - debugString = fmt.Sprintf("", debugString) - data, _ := json.Marshal(debugString) - toCache := []prebid_cache_client.Cacheable{ - { - Type: prebid_cache_client.TypeXML, - Data: data, - TTLSeconds: int64(deps.cfg.CacheURL.DefaultTTLs.Video), - Key: fmt.Sprintf("log_%s", errorCacheID), - }, + if len(debugLog.cacheKey) > 0 && vo.VideoResponse == nil { + debugLog.data = fmt.Sprintf("", debugLog.data) + data, err := json.Marshal(debugLog.data) + if err == nil { + toCache := []prebid_cache_client.Cacheable{ + { + Type: debugLog.cacheType, + Data: data, + 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)) + defer cancel() + deps.cache.PutJson(ctx, toCache) + } } - cache.PutJson(context.Background(), toCache) } deps.metricsEngine.RecordRequest(labels) deps.metricsEngine.RecordRequestTime(labels, time.Since(start)) @@ -113,15 +134,15 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re } requestJson, err := ioutil.ReadAll(lr) if err != nil { - handleError(&labels, w, []error{err}, &vo, enableDebug, &errorCacheID) + handleError(&labels, w, []error{err}, &vo, &debugLog) return } resolvedRequest := requestJson - if enableDebug { - debugString = fmt.Sprintf("Request:\n%s", string(requestJson)) + if debugLog.enableDebug { + debugLog.data = fmt.Sprintf("Request:\n%s", string(requestJson)) headerBytes, _ := json.Marshal(r.Header) - debugString = fmt.Sprintf("%s\n\nHeaders:\n%s", debugString, string(headerBytes)) + debugLog.data = fmt.Sprintf("%s\n\nHeaders:\n%s", debugLog.data, string(headerBytes)) } //load additional data - stored simplified req @@ -129,27 +150,27 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re if err != nil { if deps.cfg.VideoStoredRequestRequired { - handleError(&labels, w, []error{err}, &vo, enableDebug, &errorCacheID) + handleError(&labels, w, []error{err}, &vo, &debugLog) return } } else { storedRequest, errs := deps.loadStoredVideoRequest(context.Background(), storedRequestId) if len(errs) > 0 { - handleError(&labels, w, errs, &vo, enableDebug, &errorCacheID) + handleError(&labels, w, errs, &vo, &debugLog) return } //merge incoming req with stored video req resolvedRequest, err = jsonpatch.MergePatch(storedRequest, requestJson) if err != nil { - handleError(&labels, w, []error{err}, &vo, enableDebug, &errorCacheID) + handleError(&labels, w, []error{err}, &vo, &debugLog) return } } //unmarshal and validate combined result videoBidReq, errL, podErrors := deps.parseVideoRequest(resolvedRequest, r.Header) if len(errL) > 0 { - handleError(&labels, w, errL, &vo, enableDebug, &errorCacheID) + handleError(&labels, w, errL, &vo, &debugLog) return } @@ -159,7 +180,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re if deps.defaultRequest { if err := json.Unmarshal(deps.defReqJSON, bidReq); err != nil { err = fmt.Errorf("Invalid JSON in Default Request Settings: %s", err) - handleError(&labels, w, []error{err}, &vo, enableDebug, &errorCacheID) + handleError(&labels, w, []error{err}, &vo, &debugLog) return } } @@ -167,7 +188,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 enableDebug { + if debugLog.enableDebug { bidReq.Test = 1 } @@ -187,7 +208,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re } err := errors.New(fmt.Sprintf("all pods are incorrect: %s", strings.Join(resPodErr, "; "))) errL = append(errL, err) - handleError(&labels, w, errL, &vo, enableDebug, &errorCacheID) + handleError(&labels, w, errL, &vo, &debugLog) return } @@ -199,7 +220,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re errL = deps.validateRequest(bidReq) if len(errL) > 0 { - handleError(&labels, w, errL, &vo, enableDebug, &errorCacheID) + handleError(&labels, w, errL, &vo, &debugLog) return } @@ -227,16 +248,16 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re if acctIdErr := validateAccount(deps.cfg, labels.PubID); acctIdErr != nil { errL = append(errL, acctIdErr) - handleError(&labels, w, errL, &vo, enableDebug, &errorCacheID) + handleError(&labels, w, errL, &vo, &debugLog) return } //execute auction logic - response, err := deps.ex.HoldAuction(ctx, bidReq, usersyncs, labels, &deps.categories, debugString) + response, err := deps.ex.HoldAuction(ctx, bidReq, usersyncs, labels, &deps.categories, debugLog.data) vo.Request = bidReq vo.Response = response if err != nil { errL := []error{err} - handleError(&labels, w, errL, &vo, enableDebug, &errorCacheID) + handleError(&labels, w, errL, &vo, &debugLog) return } @@ -244,7 +265,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re bidResp, err := buildVideoResponse(response, podErrors) if err != nil { errL := []error{err} - handleError(&labels, w, errL, &vo, enableDebug, &errorCacheID) + handleError(&labels, w, errL, &vo, &debugLog) return } if bidReq.Test == 1 { @@ -257,7 +278,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re //resp, err := json.Marshal(response) if err != nil { errL := []error{err} - handleError(&labels, w, errL, &vo, enableDebug, &errorCacheID) + handleError(&labels, w, errL, &vo, &debugLog) return } @@ -273,12 +294,12 @@ func cleanupVideoBidRequest(videoReq *openrtb_ext.BidRequestVideo, podErrors []P return videoReq } -func handleError(labels *pbsmetrics.Labels, w http.ResponseWriter, errL []error, vo *analytics.VideoObject, enableDebug bool, errorCacheID *string) { - if enableDebug { +func handleError(labels *pbsmetrics.Labels, w http.ResponseWriter, errL []error, vo *analytics.VideoObject, debugLog *DebugLog) { + if debugLog != nil && debugLog.enableDebug { if rawUUID, _ := uuid.NewV4(); len(rawUUID) > 0 { - *errorCacheID = rawUUID.String() + debugLog.cacheKey = rawUUID.String() } - errL = append(errL, fmt.Errorf("Debug cache ID: [%s]", *errorCacheID)) + errL = append(errL, fmt.Errorf("Debug cache ID: [%s]", debugLog.cacheKey)) } labels.RequestStatus = pbsmetrics.RequestStatusErr var errors string diff --git a/endpoints/openrtb2/video_auction_test.go b/endpoints/openrtb2/video_auction_test.go index fe4e8ed81a4..3175fca2628 100644 --- a/endpoints/openrtb2/video_auction_test.go +++ b/endpoints/openrtb2/video_auction_test.go @@ -715,8 +715,7 @@ func TestHandleError(t *testing.T) { recorder := httptest.NewRecorder() err1 := errors.New("Error for testing handleError 1") err2 := errors.New("Error for testing handleError 2") - errorCacheID := "" - handleError(&labels, recorder, []error{err1, err2}, &vo, false, &errorCacheID) + handleError(&labels, recorder, []error{err1, err2}, &vo, nil) 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") @@ -838,6 +837,7 @@ func mockDepsWithMetrics(t *testing.T, ex *mockExchangeVideo) (*endpointDeps, *p false, []byte{}, openrtb_ext.BidderMap, + nil, } return edep, theMetrics, mockModule @@ -877,6 +877,7 @@ func mockDeps(t *testing.T, ex *mockExchangeVideo) *endpointDeps { false, []byte{}, openrtb_ext.BidderMap, + nil, } return edep diff --git a/exchange/exchange.go b/exchange/exchange.go index f9cb94a394f..660f9116ca9 100644 --- a/exchange/exchange.go +++ b/exchange/exchange.go @@ -31,7 +31,6 @@ import ( type Exchange interface { // HoldAuction executes an OpenRTB v2.5 Auction. HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, usersyncs IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, debugLog string) (*openrtb.BidResponse, error) - GetCache() prebid_cache_client.Client } // IdFetcher can find the user's ID for a specific Bidder. @@ -143,6 +142,7 @@ func (e *exchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidReque adapterBids, adapterExtra, anyBidsReturned := e.getAllBids(auctionCtx, cleanRequests, aliases, bidAdjustmentFactors, blabels, conversions) var auc *auction = nil + var bidResponseExt *openrtb_ext.ExtBidResponse = nil if anyBidsReturned { var bidCategory map[string]string @@ -164,24 +164,9 @@ func (e *exchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidReque if targData != nil { auc.setRoundedPrices(targData.priceGranularity) if len(debugLog) > 0 { - // Build the response so far - debugBidResp, _ := e.buildBidResponse(ctx, liveAdapters, adapterBids, bidRequest, resolvedRequest, adapterExtra, auc, errs) - - // Remove the VAST object from the request - for i := 0; i < len(debugBidResp.SeatBid); i++ { - for j := 0; j < len(debugBidResp.SeatBid[i].Bid); j++ { - debugBidResp.SeatBid[i].Bid[j].AdM = "" - } - } - - // Remove the resolved request due to including duplicate info - var respExt openrtb_ext.ExtBidResponse - json.Unmarshal(debugBidResp.Ext, &respExt) - respExt.Debug.ResolvedRequest = nil - debugBidResp.Ext, _ = json.Marshal(respExt) - - bidRespBytes, _ := json.Marshal(debugBidResp) - debugLog = fmt.Sprintf("", debugLog, string(bidRespBytes)) + bidResponseExt = e.makeExtBidResponse(adapterBids, adapterExtra, bidRequest, resolvedRequest, errs) + bidRespExtBytes, _ := json.Marshal(bidResponseExt) + debugLog = fmt.Sprintf("", debugLog, string(bidRespExtBytes)) } cacheErrs := auc.doCache(ctx, e.cache, targData, bidRequest, 60, &e.defaultTTLs, bidCategory, debugLog) if len(cacheErrs) > 0 { @@ -197,11 +182,7 @@ func (e *exchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidReque } // Build the response - return e.buildBidResponse(ctx, liveAdapters, adapterBids, bidRequest, resolvedRequest, adapterExtra, auc, errs) -} - -func (e *exchange) GetCache() prebid_cache_client.Client { - return e.cache + return e.buildBidResponse(ctx, liveAdapters, adapterBids, bidRequest, resolvedRequest, adapterExtra, auc, bidResponseExt, errs) } type DealTierInfo struct { @@ -419,7 +400,7 @@ func errsToBidderErrors(errs []error) []openrtb_ext.ExtBidderError { } // This piece takes all the bids supplied by the adapters and crafts an openRTB response to send back to the requester -func (e *exchange) buildBidResponse(ctx context.Context, liveAdapters []openrtb_ext.BidderName, adapterBids map[openrtb_ext.BidderName]*pbsOrtbSeatBid, bidRequest *openrtb.BidRequest, resolvedRequest json.RawMessage, adapterExtra map[openrtb_ext.BidderName]*seatResponseExtra, auc *auction, errList []error) (*openrtb.BidResponse, error) { +func (e *exchange) buildBidResponse(ctx context.Context, liveAdapters []openrtb_ext.BidderName, adapterBids map[openrtb_ext.BidderName]*pbsOrtbSeatBid, bidRequest *openrtb.BidRequest, resolvedRequest json.RawMessage, adapterExtra map[openrtb_ext.BidderName]*seatResponseExtra, auc *auction, bidResponseExt *openrtb_ext.ExtBidResponse, errList []error) (*openrtb.BidResponse, error) { bidResponse := new(openrtb.BidResponse) bidResponse.ID = bidRequest.ID @@ -442,7 +423,9 @@ func (e *exchange) buildBidResponse(ctx context.Context, liveAdapters []openrtb_ bidResponse.SeatBid = seatBids - bidResponseExt := e.makeExtBidResponse(adapterBids, adapterExtra, bidRequest, resolvedRequest, errList) + if bidResponseExt == nil { + bidResponseExt = e.makeExtBidResponse(adapterBids, adapterExtra, bidRequest, resolvedRequest, errList) + } buffer := &bytes.Buffer{} enc := json.NewEncoder(buffer) enc.SetEscapeHTML(false) diff --git a/exchange/exchange_test.go b/exchange/exchange_test.go index f5bfe2f5a50..eb4752f415f 100644 --- a/exchange/exchange_test.go +++ b/exchange/exchange_test.go @@ -127,7 +127,7 @@ func TestCharacterEscape(t *testing.T) { var errList []error /* 4) Build bid response */ - bidResp, err := e.buildBidResponse(context.Background(), liveAdapters, adapterBids, bidRequest, resolvedRequest, adapterExtra, nil, errList) + bidResp, err := e.buildBidResponse(context.Background(), liveAdapters, adapterBids, bidRequest, resolvedRequest, adapterExtra, nil, nil, errList) /* 5) Assert we have no errors and one '&' character as we are supposed to */ if err != nil { @@ -279,7 +279,7 @@ func TestGetBidCacheInfo(t *testing.T) { var errList []error /* 4) Build bid response */ - bid_resp, err := e.buildBidResponse(context.Background(), liveAdapters, adapterBids, bidRequest, resolvedRequest, adapterExtra, auc, errList) + bid_resp, err := e.buildBidResponse(context.Background(), liveAdapters, adapterBids, bidRequest, resolvedRequest, adapterExtra, auc, nil, errList) /* 5) Assert we have no errors and the bid response we expected*/ assert.NoError(t, err, "[TestGetBidCacheInfo] buildBidResponse() threw an error") @@ -450,7 +450,7 @@ func TestBidResponseCurrency(t *testing.T) { // Run tests for i := range testCases { - actualBidResp, err := e.buildBidResponse(context.Background(), liveAdapters, testCases[i].adapterBids, bidRequest, resolvedRequest, adapterExtra, nil, errList) + actualBidResp, err := e.buildBidResponse(context.Background(), liveAdapters, testCases[i].adapterBids, bidRequest, resolvedRequest, adapterExtra, nil, nil, errList) assert.NoError(t, err, fmt.Sprintf("[TEST_FAILED] e.buildBidResponse resturns error in test: %s Error message: %s \n", testCases[i].description, err)) assert.Equalf(t, testCases[i].expectedBidResponse, actualBidResp, fmt.Sprintf("[TEST_FAILED] Objects must be equal for test: %s \n Expected: >>%s<< \n Actual: >>%s<< ", testCases[i].description, testCases[i].expectedBidResponse.Ext, actualBidResp.Ext)) } diff --git a/router/router.go b/router/router.go index 7e713ca637a..8ac463b85a0 100644 --- a/router/router.go +++ b/router/router.go @@ -251,7 +251,7 @@ func New(cfg *config.Configuration, rateConvertor *currencies.RateConverter) (r glog.Fatalf("Failed to create the amp endpoint handler. %v", err) } - videoEndpoint, err := openrtb2.NewVideoEndpoint(theExchange, paramsValidator, fetcher, videoFetcher, categoriesFetcher, cfg, r.MetricsEngine, pbsAnalytics, disabledBidders, defReqJSON, activeBiddersMap) + videoEndpoint, err := openrtb2.NewVideoEndpoint(theExchange, paramsValidator, fetcher, videoFetcher, categoriesFetcher, cfg, r.MetricsEngine, pbsAnalytics, disabledBidders, defReqJSON, activeBiddersMap, cacheClient) if err != nil { glog.Fatalf("Failed to create the video endpoint handler. %v", err) } From ac698c849c8189ed13770d9830d6f404bc8f5fd1 Mon Sep 17 00:00:00 2001 From: Cameron Rice Date: Sun, 15 Mar 2020 13:14:05 -0700 Subject: [PATCH 6/8] Further code cleanup and added unit tests for debug changes --- endpoints/openrtb2/amp_auction.go | 2 +- endpoints/openrtb2/amp_auction_test.go | 7 +- endpoints/openrtb2/auction.go | 2 +- endpoints/openrtb2/auction_test.go | 19 +-- endpoints/openrtb2/video_auction.go | 48 +++--- endpoints/openrtb2/video_auction_test.go | 143 +++++++++++++++- exchange/auction.go | 13 +- exchange/auction_test.go | 3 +- exchange/cachetest/debuglog_disabled.json | 54 +++++++ exchange/cachetest/debuglog_enabled.json | 58 +++++++ exchange/exchange.go | 16 +- exchange/exchange_test.go | 22 ++- exchange/exchangetest/debuglog_disabled.json | 161 +++++++++++++++++++ exchange/exchangetest/debuglog_enabled.json | 161 +++++++++++++++++++ exchange/targeting_test.go | 2 +- 15 files changed, 638 insertions(+), 73 deletions(-) create mode 100644 exchange/cachetest/debuglog_disabled.json create mode 100644 exchange/cachetest/debuglog_enabled.json create mode 100644 exchange/exchangetest/debuglog_disabled.json create mode 100644 exchange/exchangetest/debuglog_enabled.json diff --git a/endpoints/openrtb2/amp_auction.go b/endpoints/openrtb2/amp_auction.go index ede666cf90f..8edc1e13787 100644 --- a/endpoints/openrtb2/amp_auction.go +++ b/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 { diff --git a/endpoints/openrtb2/amp_auction_test.go b/endpoints/openrtb2/amp_auction_test.go index 45617b5ccef..39d1e13c50d 100644 --- a/endpoints/openrtb2/amp_auction_test.go +++ b/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 diff --git a/endpoints/openrtb2/auction.go b/endpoints/openrtb2/auction.go index 1050a89f99e..d9c31eca98c 100644 --- a/endpoints/openrtb2/auction.go +++ b/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 { diff --git a/endpoints/openrtb2/auction_test.go b/endpoints/openrtb2/auction_test.go index 8e9c12e9f16..74a70c69415 100644 --- a/endpoints/openrtb2/auction_test.go +++ b/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 { diff --git a/endpoints/openrtb2/video_auction.go b/endpoints/openrtb2/video_auction.go index 4791bbf7608..b16f2a4f3a8 100644 --- a/endpoints/openrtb2/video_auction.go +++ b/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("", debugLog.data) - data, err := json.Marshal(debugLog.data) + if len(debugLog.CacheKey) > 0 && vo.VideoResponse == nil { + debugLog.Data = fmt.Sprintf("", 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 diff --git a/endpoints/openrtb2/video_auction_test.go b/endpoints/openrtb2/video_auction_test.go index 3175fca2628..5e41ef91ef4 100644 --- a/endpoints/openrtb2/video_auction_test.go +++ b/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}}}`), diff --git a/exchange/auction.go b/exchange/auction.go index 9a21b2e36a9..9909b78dd87 100644 --- a/exchange/auction.go +++ b/exchange/auction.go @@ -60,7 +60,7 @@ func (a *auction) setRoundedPrices(priceGranularity openrtb_ext.PriceGranularity a.roundedPrices = roundedPrices } -func (a *auction) doCache(ctx context.Context, cache prebid_cache_client.Client, targData *targetData, bidRequest *openrtb.BidRequest, ttlBuffer int64, defaultTTLs *config.DefaultTTLs, bidCategory map[string]string, debugLog string) []error { +func (a *auction) doCache(ctx context.Context, cache prebid_cache_client.Client, targData *targetData, bidRequest *openrtb.BidRequest, ttlBuffer int64, defaultTTLs *config.DefaultTTLs, bidCategory map[string]string, debugLog *DebugLog) []error { var bids, vast, includeBidderKeys, includeWinners bool = targData.includeCacheBids, targData.includeCacheVast, targData.includeBidderKeys, targData.includeWinners if !((bids || vast) && (includeBidderKeys || includeWinners)) { return nil @@ -147,13 +147,14 @@ func (a *auction) doCache(ctx context.Context, cache prebid_cache_client.Client, } } - if len(debugLog) > 0 { - if jsonBytes, err := json.Marshal(debugLog); err == nil { + if debugLog != nil && debugLog.EnableDebug { + debugLog.CacheKey = hbCacheID + if jsonBytes, err := json.Marshal(debugLog.Data); err == nil { toCache = append(toCache, prebid_cache_client.Cacheable{ - Type: prebid_cache_client.TypeXML, + Type: debugLog.CacheType, Data: jsonBytes, - TTLSeconds: defTTL(openrtb_ext.BidTypeVideo, defaultTTLs), - Key: fmt.Sprintf("log_%s", hbCacheID), + TTLSeconds: debugLog.TTL, + Key: "log_" + debugLog.CacheKey, }) } } diff --git a/exchange/auction_test.go b/exchange/auction_test.go index 705f17f1f2f..d23ff03e00a 100644 --- a/exchange/auction_test.go +++ b/exchange/auction_test.go @@ -188,7 +188,7 @@ func runCacheSpec(t *testing.T, fileDisplayName string, specData *cacheSpec) { winningBidsByBidder: winningBidsByBidder, roundedPrices: roundedPrices, } - _ = testAuction.doCache(ctx, cache, targData, &specData.BidRequest, 60, &specData.DefaultTTLs, bidCategory, "") + _ = testAuction.doCache(ctx, cache, targData, &specData.BidRequest, 60, &specData.DefaultTTLs, bidCategory, &specData.DebugLog) if len(specData.ExpectedCacheables) > len(cache.items) { t.Errorf("%s: [CACHE_ERROR] Less elements were cached than expected \n", fileDisplayName) @@ -232,6 +232,7 @@ type cacheSpec struct { TargetDataIncludeBidderKeys bool `json:"targetDataIncludeBidderKeys"` TargetDataIncludeCacheBids bool `json:"targetDataIncludeCacheBids"` TargetDataIncludeCacheVast bool `json:"targetDataIncludeCacheVast"` + DebugLog DebugLog `json:"debugLog,omitempty"` } type pbsBid struct { diff --git a/exchange/cachetest/debuglog_disabled.json b/exchange/cachetest/debuglog_disabled.json new file mode 100644 index 00000000000..675488c04d1 --- /dev/null +++ b/exchange/cachetest/debuglog_disabled.json @@ -0,0 +1,54 @@ +{ + "debugLog": { + "EnableDebug": false, + "CacheType": "xml", + "TTL": 3600, + "Data": "test debug data" + }, + "bidRequest": { + "imp": [{ + "id": "oneImp", + "exp": 600 + }, { + "id": "twoImp" + }] + }, + "pbsBids": [{ + "bid":{ + "id": "bidOne", + "impid": "oneImp", + "price": 7.64 + }, + "bidType": "video", + "bidder": "appnexus" + }, { + "bid": { + "id": "bidTwo", + "impid": "twoImp", + "price": 5.64 + }, + "bidType": "video", + "bidder": "pubmatic" + }], + "expectedCacheables": [ + { + "Type": "json", + "TTLSeconds": 660, + "Data": "{\"id\": \"bidOne\", \"impid\": \"oneImp\", \"price\": 7.64}" + }, { + "Type": "json", + "TTLSeconds": 3660, + "Data": "{\"id\": \"bidTwo\", \"impid\": \"twoImp\", \"price\": 5.64}" + } + ], + "defaultTTLs": { + "banner": 300, + "video": 3600, + "audio": 1800, + "native": 300 + }, + "targetDataIncludeWinners":true, + "targetDataIncludeBidderKeys":true, + "targetDataIncludeCacheBids":true, + "targetDataIncludeCacheVast":false +} diff --git a/exchange/cachetest/debuglog_enabled.json b/exchange/cachetest/debuglog_enabled.json new file mode 100644 index 00000000000..d4486558a54 --- /dev/null +++ b/exchange/cachetest/debuglog_enabled.json @@ -0,0 +1,58 @@ +{ + "debugLog": { + "EnableDebug": true, + "CacheType": "xml", + "TTL": 3600, + "Data": "test debug data" + }, + "bidRequest": { + "imp": [{ + "id": "oneImp", + "exp": 600 + }, { + "id": "twoImp" + }] + }, + "pbsBids": [{ + "bid":{ + "id": "bidOne", + "impid": "oneImp", + "price": 7.64 + }, + "bidType": "video", + "bidder": "appnexus" + }, { + "bid": { + "id": "bidTwo", + "impid": "twoImp", + "price": 5.64 + }, + "bidType": "video", + "bidder": "pubmatic" + }], + "expectedCacheables": [ + { + "Type": "json", + "TTLSeconds": 660, + "Data": "{\"id\": \"bidOne\", \"impid\": \"oneImp\", \"price\": 7.64}" + }, { + "Type": "json", + "TTLSeconds": 3660, + "Data": "{\"id\": \"bidTwo\", \"impid\": \"twoImp\", \"price\": 5.64}" + }, { + "Type": "xml", + "TTLSeconds": 3600, + "Data": "test debug data" + } + ], + "defaultTTLs": { + "banner": 300, + "video": 3600, + "audio": 1800, + "native": 300 + }, + "targetDataIncludeWinners":true, + "targetDataIncludeBidderKeys":true, + "targetDataIncludeCacheBids":true, + "targetDataIncludeCacheVast":false +} diff --git a/exchange/exchange.go b/exchange/exchange.go index 660f9116ca9..1d6cdb42fba 100644 --- a/exchange/exchange.go +++ b/exchange/exchange.go @@ -27,10 +27,18 @@ import ( "github.com/prebid/prebid-server/prebid_cache_client" ) +type DebugLog struct { + EnableDebug bool + CacheType prebid_cache_client.PayloadType + Data string + TTL int64 + CacheKey string +} + // Exchange runs Auctions. Implementations must be threadsafe, and will be shared across many goroutines. type Exchange interface { // HoldAuction executes an OpenRTB v2.5 Auction. - HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, usersyncs IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, debugLog string) (*openrtb.BidResponse, error) + HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, usersyncs IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, debugLog *DebugLog) (*openrtb.BidResponse, error) } // IdFetcher can find the user's ID for a specific Bidder. @@ -78,7 +86,7 @@ func NewExchange(client *http.Client, cache prebid_cache_client.Client, cfg *con return e } -func (e *exchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, usersyncs IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, debugLog string) (*openrtb.BidResponse, error) { +func (e *exchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidRequest, usersyncs IdFetcher, labels pbsmetrics.Labels, categoriesFetcher *stored_requests.CategoryFetcher, debugLog *DebugLog) (*openrtb.BidResponse, error) { // Snapshot of resolved bid request for debug if test request resolvedRequest, err := buildResolvedRequest(bidRequest) if err != nil { @@ -163,10 +171,10 @@ func (e *exchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidReque if targData != nil { auc.setRoundedPrices(targData.priceGranularity) - if len(debugLog) > 0 { + if debugLog != nil && debugLog.EnableDebug { bidResponseExt = e.makeExtBidResponse(adapterBids, adapterExtra, bidRequest, resolvedRequest, errs) bidRespExtBytes, _ := json.Marshal(bidResponseExt) - debugLog = fmt.Sprintf("", debugLog, string(bidRespExtBytes)) + debugLog.Data = fmt.Sprintf("", debugLog.Data, string(bidRespExtBytes)) } cacheErrs := auc.doCache(ctx, e.cache, targData, bidRequest, 60, &e.defaultTTLs, bidCategory, debugLog) if len(cacheErrs) > 0 { diff --git a/exchange/exchange_test.go b/exchange/exchange_test.go index eb4752f415f..7217e609189 100644 --- a/exchange/exchange_test.go +++ b/exchange/exchange_test.go @@ -489,7 +489,7 @@ func TestRaceIntegration(t *testing.T) { } theMetrics := pbsmetrics.NewMetrics(metrics.NewRegistry(), openrtb_ext.BidderList(), config.DisabledMetrics{}) ex := NewExchange(server.Client(), &wellBehavedCache{}, cfg, theMetrics, adapters.ParseBidderInfos(cfg.Adapters, "../static/bidder-info", openrtb_ext.BidderList()), gdpr.AlwaysAllow{}, currencies.NewRateConverterDefault()) - _, err := ex.HoldAuction(context.Background(), newRaceCheckingRequest(t), &emptyUsersync{}, pbsmetrics.Labels{}, &categoriesFetcher, "") + _, err := ex.HoldAuction(context.Background(), newRaceCheckingRequest(t), &emptyUsersync{}, pbsmetrics.Labels{}, &categoriesFetcher, nil) if err != nil { t.Errorf("HoldAuction returned unexpected error: %v", err) } @@ -666,7 +666,7 @@ func TestPanicRecoveryHighLevel(t *testing.T) { if error != nil { t.Errorf("Failed to create a category Fetcher: %v", error) } - _, err := e.HoldAuction(context.Background(), request, &emptyUsersync{}, pbsmetrics.Labels{}, &categoriesFetcher, "") + _, err := e.HoldAuction(context.Background(), request, &emptyUsersync{}, pbsmetrics.Labels{}, &categoriesFetcher, nil) if err != nil { t.Errorf("HoldAuction returned unexpected error: %v", err) } @@ -732,7 +732,11 @@ func runSpec(t *testing.T, filename string, spec *exchangeSpec) { if error != nil { t.Errorf("Failed to create a category Fetcher: %v", error) } - bid, err := ex.HoldAuction(context.Background(), &spec.IncomingRequest.OrtbRequest, mockIdFetcher(spec.IncomingRequest.Usersyncs), pbsmetrics.Labels{}, &categoriesFetcher, "") + debugLog := &DebugLog{} + if spec.DebugLog != nil { + *debugLog = *spec.DebugLog + } + bid, err := ex.HoldAuction(context.Background(), &spec.IncomingRequest.OrtbRequest, mockIdFetcher(spec.IncomingRequest.Usersyncs), pbsmetrics.Labels{}, &categoriesFetcher, debugLog) responseTimes := extractResponseTimes(t, filename, bid) for _, bidderName := range biddersInAuction { if _, ok := responseTimes[bidderName]; !ok { @@ -751,6 +755,17 @@ func runSpec(t *testing.T, filename string, spec *exchangeSpec) { } } } + if spec.DebugLog != nil { + if spec.DebugLog.EnableDebug { + if len(debugLog.Data) <= len(spec.DebugLog.Data) { + t.Errorf("%s: DebugLog was not modified when it should have been", filename) + } + } else { + if !strings.EqualFold(spec.DebugLog.Data, debugLog.Data) { + t.Errorf("%s: DebugLog was modified when it shouldn't have been", filename) + } + } + } } func findBiddersInAuction(t *testing.T, context string, req *openrtb.BidRequest) []string { @@ -1588,6 +1603,7 @@ type exchangeSpec struct { OutgoingRequests map[string]*bidderSpec `json:"outgoingRequests"` Response exchangeResponse `json:"response,omitempty"` EnforceCCPA bool `json:"enforceCcpa"` + DebugLog *DebugLog `json:"debuglog,omitempty"` } type exchangeRequest struct { diff --git a/exchange/exchangetest/debuglog_disabled.json b/exchange/exchangetest/debuglog_disabled.json new file mode 100644 index 00000000000..0c24c121935 --- /dev/null +++ b/exchange/exchangetest/debuglog_disabled.json @@ -0,0 +1,161 @@ +{ + "debugLog": { + "EnableDebug": false, + "CacheType": "xml", + "TTL": 3600, + "Data": "test debug data" + }, + "incomingRequest": { + "ortbRequest": { + "id": "some-request-id", + "site": { + "page": "test.somepage.com" + }, + "imp": [ + { + "id": "my-imp-id", + "video": { + "mimes": ["video/mp4"] + }, + "ext": { + "appnexus": { + "placementId": 1 + } + } + }, + { + "id": "imp-id-2", + "video": { + "mimes": ["video/mp4"] + }, + "ext": { + "appnexus": { + "placementId": 1 + } + } + } + ], + "ext": { + "prebid": { + "targeting": { + "includebrandcategory": { + "primaryadserver": 1, + "publisher":"", + "withcategory": true + } + } + } + } + }, + "usersyncs": { + "appnexus": "123" + } + }, + "outgoingRequests": { + "appnexus": { + "mockResponse": { + "pbsSeatBid": { + "pbsBids": [ + { + "ortbBid": { + "id": "apn-bid", + "impid": "my-imp-id", + "price": 0.3, + "w": 200, + "h": 250, + "crid": "creative-1", + "cat": ["IAB1-1"] + }, + "bidType": "video", + "bidVideo": { + "duration": 30, + "PrimaryCategory": "" + } + }, + { + "ortbBid": { + "id": "apn-other-bid", + "impid": "imp-id-2", + "price": 0.6, + "w": 300, + "h": 500, + "crid": "creative-3", + "cat": ["IAB1-2"] + }, + "bidType": "video" + } + ] + } + } + } + }, + "response": { + "bids": { + "id": "some-request-id", + "seatbid": [ + { + "seat": "appnexus", + "bid": [ + { + "id": "apn-bid", + "impid": "my-imp-id", + "price": 0.3, + "w": 200, + "h": 250, + "crid": "creative-1", + "cat": ["IAB1-1"], + "ext": { + "prebid": { + "type": "video", + "targeting": { + "hb_bidder": "appnexus", + "hb_bidder_appnexus": "appnexus", + "hb_cache_host": "www.pbcserver.com", + "hb_cache_host_appnex": "www.pbcserver.com", + "hb_cache_path": "/pbcache/endpoint", + "hb_cache_path_appnex": "/pbcache/endpoint", + "hb_pb": "0.20", + "hb_pb_appnexus": "0.20", + "hb_pb_cat_dur": "0.20_VideoGames_0s", + "hb_pb_cat_dur_appnex": "0.20_VideoGames_0s", + "hb_size": "200x250", + "hb_size_appnexus": "200x250" + } + } + } + }, + { + "cat": ["IAB1-2"], + "crid": "creative-3", + "ext": { + "prebid": { + "targeting": { + "hb_bidder": "appnexus", + "hb_bidder_appnexus": "appnexus", + "hb_cache_host": "www.pbcserver.com", + "hb_cache_host_appnex": "www.pbcserver.com", + "hb_cache_path": "/pbcache/endpoint", + "hb_cache_path_appnex": "/pbcache/endpoint", + "hb_pb": "0.50", + "hb_pb_appnexus": "0.50", + "hb_pb_cat_dur": "0.50_HomeDecor_0s", + "hb_pb_cat_dur_appnex": "0.50_HomeDecor_0s", + "hb_size": "300x500", + "hb_size_appnexus": "300x500" + }, + "type": "video" + } + }, + "h": 500, + "id": "apn-other-bid", + "impid": "imp-id-2", + "price": 0.6, + "w": 300 + } + ] + } + ] + } + } + } + \ No newline at end of file diff --git a/exchange/exchangetest/debuglog_enabled.json b/exchange/exchangetest/debuglog_enabled.json new file mode 100644 index 00000000000..281bf3a1b4e --- /dev/null +++ b/exchange/exchangetest/debuglog_enabled.json @@ -0,0 +1,161 @@ +{ + "debugLog": { + "EnableDebug": true, + "CacheType": "xml", + "TTL": 3600, + "Data": "test debug data" + }, + "incomingRequest": { + "ortbRequest": { + "id": "some-request-id", + "site": { + "page": "test.somepage.com" + }, + "imp": [ + { + "id": "my-imp-id", + "video": { + "mimes": ["video/mp4"] + }, + "ext": { + "appnexus": { + "placementId": 1 + } + } + }, + { + "id": "imp-id-2", + "video": { + "mimes": ["video/mp4"] + }, + "ext": { + "appnexus": { + "placementId": 1 + } + } + } + ], + "ext": { + "prebid": { + "targeting": { + "includebrandcategory": { + "primaryadserver": 1, + "publisher":"", + "withcategory": true + } + } + } + } + }, + "usersyncs": { + "appnexus": "123" + } + }, + "outgoingRequests": { + "appnexus": { + "mockResponse": { + "pbsSeatBid": { + "pbsBids": [ + { + "ortbBid": { + "id": "apn-bid", + "impid": "my-imp-id", + "price": 0.3, + "w": 200, + "h": 250, + "crid": "creative-1", + "cat": ["IAB1-1"] + }, + "bidType": "video", + "bidVideo": { + "duration": 30, + "PrimaryCategory": "" + } + }, + { + "ortbBid": { + "id": "apn-other-bid", + "impid": "imp-id-2", + "price": 0.6, + "w": 300, + "h": 500, + "crid": "creative-3", + "cat": ["IAB1-2"] + }, + "bidType": "video" + } + ] + } + } + } + }, + "response": { + "bids": { + "id": "some-request-id", + "seatbid": [ + { + "seat": "appnexus", + "bid": [ + { + "id": "apn-bid", + "impid": "my-imp-id", + "price": 0.3, + "w": 200, + "h": 250, + "crid": "creative-1", + "cat": ["IAB1-1"], + "ext": { + "prebid": { + "type": "video", + "targeting": { + "hb_bidder": "appnexus", + "hb_bidder_appnexus": "appnexus", + "hb_cache_host": "www.pbcserver.com", + "hb_cache_host_appnex": "www.pbcserver.com", + "hb_cache_path": "/pbcache/endpoint", + "hb_cache_path_appnex": "/pbcache/endpoint", + "hb_pb": "0.20", + "hb_pb_appnexus": "0.20", + "hb_pb_cat_dur": "0.20_VideoGames_0s", + "hb_pb_cat_dur_appnex": "0.20_VideoGames_0s", + "hb_size": "200x250", + "hb_size_appnexus": "200x250" + } + } + } + }, + { + "cat": ["IAB1-2"], + "crid": "creative-3", + "ext": { + "prebid": { + "targeting": { + "hb_bidder": "appnexus", + "hb_bidder_appnexus": "appnexus", + "hb_cache_host": "www.pbcserver.com", + "hb_cache_host_appnex": "www.pbcserver.com", + "hb_cache_path": "/pbcache/endpoint", + "hb_cache_path_appnex": "/pbcache/endpoint", + "hb_pb": "0.50", + "hb_pb_appnexus": "0.50", + "hb_pb_cat_dur": "0.50_HomeDecor_0s", + "hb_pb_cat_dur_appnex": "0.50_HomeDecor_0s", + "hb_size": "300x500", + "hb_size_appnexus": "300x500" + }, + "type": "video" + } + }, + "h": 500, + "id": "apn-other-bid", + "impid": "imp-id-2", + "price": 0.6, + "w": 300 + } + ] + } + ] + } + } + } + \ No newline at end of file diff --git a/exchange/targeting_test.go b/exchange/targeting_test.go index 7e97080fc0d..f86309684c6 100644 --- a/exchange/targeting_test.go +++ b/exchange/targeting_test.go @@ -106,7 +106,7 @@ func runTargetingAuction(t *testing.T, mockBids map[openrtb_ext.BidderName][]*op if error != nil { t.Errorf("Failed to create a category Fetcher: %v", error) } - bidResp, err := ex.HoldAuction(context.Background(), req, &mockFetcher{}, pbsmetrics.Labels{}, &categoriesFetcher, "") + bidResp, err := ex.HoldAuction(context.Background(), req, &mockFetcher{}, pbsmetrics.Labels{}, &categoriesFetcher, nil) if err != nil { t.Fatalf("Unexpected errors running auction: %v", err) From 87b1b65c08ccae0185cb741217d4ee7b25d50e70 Mon Sep 17 00:00:00 2001 From: Cameron Rice Date: Mon, 16 Mar 2020 09:23:23 -0700 Subject: [PATCH 7/8] Added missing error checks --- endpoints/openrtb2/video_auction.go | 11 ++++++----- exchange/exchange.go | 7 +++++-- 2 files changed, 11 insertions(+), 7 deletions(-) diff --git a/endpoints/openrtb2/video_auction.go b/endpoints/openrtb2/video_auction.go index b16f2a4f3a8..0367cfce5f5 100644 --- a/endpoints/openrtb2/video_auction.go +++ b/endpoints/openrtb2/video_auction.go @@ -107,9 +107,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re }, } if deps.cache != nil { - ctx := context.Background() - var cancel context.CancelFunc - ctx, cancel = context.WithDeadline(ctx, start.Add(time.Duration(100)*time.Millisecond)) + ctx, cancel := context.WithDeadline(context.Background(), start.Add(time.Duration(100)*time.Millisecond)) defer cancel() deps.cache.PutJson(ctx, toCache) } @@ -133,8 +131,11 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re resolvedRequest := 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)) + if headerBytes, err := json.Marshal(r.Header); err == nil { + debugLog.Data = fmt.Sprintf("%s\n\nHeaders:\n%s", debugLog.Data, string(headerBytes)) + } else { + debugLog.Data = fmt.Sprintf("%s\n\nUnable to marshal headers data\n", debugLog.Data) + } } //load additional data - stored simplified req diff --git a/exchange/exchange.go b/exchange/exchange.go index 1d6cdb42fba..995add3d496 100644 --- a/exchange/exchange.go +++ b/exchange/exchange.go @@ -173,8 +173,11 @@ func (e *exchange) HoldAuction(ctx context.Context, bidRequest *openrtb.BidReque auc.setRoundedPrices(targData.priceGranularity) if debugLog != nil && debugLog.EnableDebug { bidResponseExt = e.makeExtBidResponse(adapterBids, adapterExtra, bidRequest, resolvedRequest, errs) - bidRespExtBytes, _ := json.Marshal(bidResponseExt) - debugLog.Data = fmt.Sprintf("", debugLog.Data, string(bidRespExtBytes)) + if bidRespExtBytes, err := json.Marshal(bidResponseExt); err == nil { + debugLog.Data = fmt.Sprintf("", debugLog.Data, string(bidRespExtBytes)) + } else { + errs = append(errs, errors.New("Unable to marshal response ext for debugging")) + } } cacheErrs := auc.doCache(ctx, e.cache, targData, bidRequest, 60, &e.defaultTTLs, bidCategory, debugLog) if len(cacheErrs) > 0 { From b01d04d19d765f61d35e60cffa2d331f25027adf Mon Sep 17 00:00:00 2001 From: Cameron Rice Date: Tue, 17 Mar 2020 09:22:21 -0700 Subject: [PATCH 8/8] Added unit test for error case --- endpoints/openrtb2/video_auction.go | 2 +- endpoints/openrtb2/video_auction_test.go | 25 ++++++++++++++++++++++++ 2 files changed, 26 insertions(+), 1 deletion(-) diff --git a/endpoints/openrtb2/video_auction.go b/endpoints/openrtb2/video_auction.go index 0367cfce5f5..630a3f5acd3 100644 --- a/endpoints/openrtb2/video_auction.go +++ b/endpoints/openrtb2/video_auction.go @@ -289,7 +289,7 @@ func cleanupVideoBidRequest(videoReq *openrtb_ext.BidRequestVideo, podErrors []P 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 { + if rawUUID, err := uuid.NewV4(); err == nil { debugLog.CacheKey = rawUUID.String() } errL = append(errL, fmt.Errorf("[Debug cache ID: %s]", debugLog.CacheKey)) diff --git a/endpoints/openrtb2/video_auction_test.go b/endpoints/openrtb2/video_auction_test.go index 5e41ef91ef4..0199b43f610 100644 --- a/endpoints/openrtb2/video_auction_test.go +++ b/endpoints/openrtb2/video_auction_test.go @@ -256,6 +256,28 @@ func TestVideoEndpointDebugQueryFalse(t *testing.T) { assert.Equal(t, resp.AdPods[4].Targeting[0].HbPbCatDur, "20.00_395_30s", "Incorrect number of Ad Pods in response") } +func TestVideoEndpointDebugError(t *testing.T) { + ex := &mockExchangeVideo{ + cache: &mockCacheClient{}, + } + reqData, err := ioutil.ReadFile("sample-requests/video/video_invalid_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.cache.called { + t.Fatalf("Cache was not called when it should have been") + } + + assert.Equal(t, recorder.Code, 500, "Should catch error in request") +} + func TestVideoEndpointNoPods(t *testing.T) { ex := &mockExchangeVideo{} reqData, err := ioutil.ReadFile("sample-requests/video/video_invalid_sample.json") @@ -1007,6 +1029,9 @@ type mockCacheClient struct { } func (m *mockCacheClient) PutJson(ctx context.Context, values []prebid_cache_client.Cacheable) ([]string, []error) { + if !m.called { + m.called = true + } return []string{}, []error{} }