Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Added logging to cache for video endpoint #1220

Merged
merged 8 commits into from
Mar 18, 2020
Merged

Added logging to cache for video endpoint #1220

Show file tree
Hide file tree
Changes from 7 commits
Commits
Show all changes
8 commits
Select commit Hold shift + click to select a range
1ac57de
WIP added logging to cache for video endpoint
Mar 12, 2020
a678b50
Updating cache call to use TTL from config
Mar 12, 2020
1f7a0aa
Updates from initial feedback
Mar 12, 2020
c60768c
Updated recorded response and handleError
Mar 13, 2020
e939e3d
Updates from code review comments
Mar 14, 2020
ac698c8
Further code cleanup and added unit tests for debug changes
Mar 15, 2020
87b1b65
Added missing error checks
Mar 16, 2020
b01d04d
Added unit test for error case
Mar 17, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
5 changes: 3 additions & 2 deletions endpoints/openrtb2/amp_auction.go
View file
Open in desktop
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
Open in desktop
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
Open in desktop
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
Open in desktop
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
Open in desktop
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)
SyntaxNode marked this conversation as resolved.
Show resolved Hide resolved
data, err := json.Marshal(debugLog.Data)
SyntaxNode marked this conversation as resolved.
Show resolved Hide resolved
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, _ := uuid.NewV4(); len(rawUUID) > 0 {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This will produce warnings that you're ignoring the error from NewV4. In practice, you're likely fine with a check on the uuid.. but checking for a non-nil error is preferred.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Updated to check the error instead

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