Skip to content
This repository has been archived by the owner on Dec 22, 2022. It is now read-only.

Commit

Permalink
Added logging to cache for video endpoint (prebid#1220)
Browse files Browse the repository at this point in the history 
* WIP added logging to cache for video endpoint

* Updating cache call to use TTL from config

* 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

* Updated recorded response and handleError

* 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

* Further code cleanup and added unit tests for debug changes

* Added missing error checks

* Added unit test for error case
  • Loading branch information
@camrice
camrice authored Mar 18, 2020
1 parent 6be6319 commit f8c5ced
Show file tree
Hide file tree
Showing 16 changed files with 749 additions and 43 deletions.
5 changes: 3 additions & 2 deletions endpoints/openrtb2/amp_auction.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -71,7 +71,8 @@ func NewAmpEndpoint(
disabledBidders,
defRequest,
defReqJSON,
bidderMap}).AmpAuction), nil
bidderMap,
nil}).AmpAuction), nil

}

Expand Down Expand Up @@ -165,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 {
Expand Down
2 changes: 1 addition & 1 deletion endpoints/openrtb2/amp_auction_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -902,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) (*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{
Expand Down
7 changes: 5 additions & 2 deletions endpoints/openrtb2/auction.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -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 {
Expand All @@ -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) {
Expand Down Expand Up @@ -137,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 {
Expand Down
14 changes: 10 additions & 4 deletions endpoints/openrtb2/auction_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -602,7 +602,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))
Expand Down Expand Up @@ -638,6 +638,7 @@ func TestOversizedRequest(t *testing.T) {
false,
[]byte{},
openrtb_ext.BidderMap,
nil,
}

req := httptest.NewRequest("POST", "/openrtb2/auction", strings.NewReader(reqBody))
Expand Down Expand Up @@ -670,6 +671,7 @@ func TestRequestSizeEdgeCase(t *testing.T) {
false,
[]byte{},
openrtb_ext.BidderMap,
nil,
}

req := httptest.NewRequest("POST", "/openrtb2/auction", strings.NewReader(reqBody))
Expand Down Expand Up @@ -807,6 +809,7 @@ func TestDisabledBidder(t *testing.T) {
false,
[]byte{},
openrtb_ext.BidderMap,
nil,
}

req := httptest.NewRequest("POST", "/openrtb2/auction", strings.NewReader(reqBody))
Expand Down Expand Up @@ -840,6 +843,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))
Expand Down Expand Up @@ -878,6 +882,7 @@ func TestCurrencyTrunc(t *testing.T) {
false,
[]byte{},
openrtb_ext.BidderMap,
nil,
}

ui := uint64(1)
Expand Down Expand Up @@ -919,6 +924,7 @@ func TestCCPAInvalidValueWarning(t *testing.T) {
false,
[]byte{},
openrtb_ext.BidderMap,
nil,
}

ui := uint64(1)
Expand Down Expand Up @@ -953,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) (*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,
Expand All @@ -964,7 +970,7 @@ func (e *nobidExchange) HoldAuction(ctx context.Context, bidRequest *openrtb.Bid

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, debugLog *exchange.DebugLog) (*openrtb.BidResponse, error) {
return nil, errors.New("Critical, unrecoverable error.")
}

Expand Down Expand Up @@ -1324,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) (*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{{
Expand Down
83 changes: 67 additions & 16 deletions endpoints/openrtb2/video_auction.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand All @@ -24,20 +25,21 @@ 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"
)

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) {
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
}

/*
Expand Down Expand Up @@ -79,7 +81,38 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re
CookieFlag: pbsmetrics.CookieFlagUnknown,
RequestStatus: pbsmetrics.RequestStatusOK,
}

debugQuery := r.URL.Query().Get("debug")
cacheTTL := int64(3600)
if deps.cfg.CacheURL.DefaultTTLs.Video > 0 {
cacheTTL = int64(deps.cfg.CacheURL.DefaultTTLs.Video)
}
debugLog := exchange.DebugLog{
EnableDebug: strings.EqualFold(debugQuery, "true"),
CacheType: prebid_cache_client.TypeXML,
TTL: cacheTTL,
}

defer func() {
if len(debugLog.CacheKey) > 0 && vo.VideoResponse == nil {
debugLog.Data = fmt.Sprintf("<!--\n%s\n\nNo response created\n-->", debugLog.Data)
data, err := json.Marshal(debugLog.Data)
if err == nil {
toCache := []prebid_cache_client.Cacheable{
{
Type: debugLog.CacheType,
Data: data,
TTLSeconds: debugLog.TTL,
Key: "log_" + debugLog.CacheKey,
},
}
if deps.cache != nil {
ctx, cancel := context.WithDeadline(context.Background(), start.Add(time.Duration(100)*time.Millisecond))
defer cancel()
deps.cache.PutJson(ctx, toCache)
}
}
}
deps.metricsEngine.RecordRequest(labels)
deps.metricsEngine.RecordRequestTime(labels, time.Since(start))
deps.analytics.LogVideoObject(&vo)
Expand All @@ -91,38 +124,46 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re
}
requestJson, err := ioutil.ReadAll(lr)
if err != nil {
handleError(&labels, w, []error{err}, &vo)
handleError(&labels, w, []error{err}, &vo, &debugLog)
return
}

resolvedRequest := requestJson
if debugLog.EnableDebug {
debugLog.Data = fmt.Sprintf("Request:\n%s", string(requestJson))
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
storedRequestId, err := getVideoStoredRequestId(requestJson)

if err != nil {
if deps.cfg.VideoStoredRequestRequired {
handleError(&labels, w, []error{err}, &vo)
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)
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)
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)
handleError(&labels, w, errL, &vo, &debugLog)
return
}

Expand All @@ -132,13 +173,17 @@ 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)
handleError(&labels, w, []error{err}, &vo, &debugLog)
return
}
}

//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 {
bidReq.Test = 1
}

initialPodNumber := len(videoBidReq.PodConfig.Pods)
if len(podErrors) > 0 {
Expand All @@ -156,7 +201,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)
handleError(&labels, w, errL, &vo, &debugLog)
return
}

Expand All @@ -168,7 +213,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re

errL = deps.validateRequest(bidReq)
if len(errL) > 0 {
handleError(&labels, w, errL, &vo)
handleError(&labels, w, errL, &vo, &debugLog)
return
}

Expand Down Expand Up @@ -196,24 +241,24 @@ 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)
handleError(&labels, w, errL, &vo, &debugLog)
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, &debugLog)
vo.Request = bidReq
vo.Response = response
if err != nil {
errL := []error{err}
handleError(&labels, w, errL, &vo)
handleError(&labels, w, errL, &vo, &debugLog)
return
}

//build simplified response
bidResp, err := buildVideoResponse(response, podErrors)
if err != nil {
errL := []error{err}
handleError(&labels, w, errL, &vo)
handleError(&labels, w, errL, &vo, &debugLog)
return
}
if bidReq.Test == 1 {
Expand All @@ -226,7 +271,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)
handleError(&labels, w, errL, &vo, &debugLog)
return
}

Expand All @@ -242,7 +287,13 @@ 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, debugLog *exchange.DebugLog) {
if debugLog != nil && debugLog.EnableDebug {
if rawUUID, err := uuid.NewV4(); err == nil {
debugLog.CacheKey = rawUUID.String()
}
errL = append(errL, fmt.Errorf("[Debug cache ID: %s]", debugLog.CacheKey))
}
labels.RequestStatus = pbsmetrics.RequestStatusErr
var errors string
var status int = http.StatusInternalServerError
Expand Down
Loading

0 comments on commit f8c5ced

Please sign in to comment.