Add timestamp to analytics and response.ext.prebid.auctiontimestamp l…

analytics/core.go

@@ -1,6 +1,8 @@
 package analytics
 
 import (
+	"time"
+
 	"github.com/mxmCherry/openrtb"
 	"github.com/prebid/prebid-server/config"
 	"github.com/prebid/prebid-server/openrtb_ext"
@@ -26,11 +28,12 @@ type PBSAnalyticsModule interface {
 
 //Loggable object of a transaction at /openrtb2/auction endpoint
 type AuctionObject struct {
-	Status   int
-	Errors   []error
-	Request  *openrtb.BidRequest
-	Response *openrtb.BidResponse
-	Account  *config.Account
+	Status    int
+	Errors    []error
+	Request   *openrtb.BidRequest
+	Response  *openrtb.BidResponse
+	Account   *config.Account
+	StartTime time.Time
 }
 
 //Loggable object of a transaction at /openrtb2/amp endpoint
@@ -41,6 +44,7 @@ type AmpObject struct {
 	AuctionResponse    *openrtb.BidResponse
 	AmpTargetingValues map[string]string
 	Origin             string
+	StartTime          time.Time
 }
 
 //Loggable object of a transaction at /openrtb2/video endpoint
@@ -51,6 +55,7 @@ type VideoObject struct {
 	Response      *openrtb.BidResponse
 	VideoRequest  *openrtb_ext.BidRequestVideo
 	VideoResponse *openrtb_ext.BidResponseVideo
+	StartTime     time.Time
 }
 
 //Loggable object of a transaction at /setuid

endpoints/openrtb2/amp_auction.go

@@ -91,18 +91,17 @@ func (deps *endpointDeps) AmpAuction(w http.ResponseWriter, r *http.Request, _ h
 	ao := analytics.AmpObject{
 		Status: http.StatusOK,
 		Errors: make([]error, 0),
+		// Prebid Server interprets request.tmax to be the maximum amount of time that a caller is willing
+		// to wait for bids. However, tmax may be defined in the Stored Request data.
+		//
+		// If so, then the trip to the backend might use a significant amount of this time.
+		// We can respect timeouts more accurately if we note the *real* start time, and use it
+		// to compute the auction timeout.
+		StartTime: time.Now(),
 	}
 
-	// Prebid Server interprets request.tmax to be the maximum amount of time that a caller is willing
-	// to wait for bids. However, tmax may be defined in the Stored Request data.
-	//
-	// If so, then the trip to the backend might use a significant amount of this time.
-	// We can respect timeouts more accurately if we note the *real* start time, and use it
-	// to compute the auction timeout.
-
 	// Set this as an AMP request in Metrics.
 
-	start := time.Now()
 	labels := pbsmetrics.Labels{
 		Source:        pbsmetrics.DemandWeb,
 		RType:         pbsmetrics.ReqTypeAMP,
@@ -113,7 +112,7 @@ func (deps *endpointDeps) AmpAuction(w http.ResponseWriter, r *http.Request, _ h
 	}
 	defer func() {
 		deps.metricsEngine.RecordRequest(labels)
-		deps.metricsEngine.RecordRequestTime(labels, time.Since(start))
+		deps.metricsEngine.RecordRequestTime(labels, time.Since(ao.StartTime))
 		deps.analytics.LogAmpObject(&ao)
 	}()
 
@@ -147,9 +146,9 @@ func (deps *endpointDeps) AmpAuction(w http.ResponseWriter, r *http.Request, _ h
 	ctx := context.Background()
 	var cancel context.CancelFunc
 	if req.TMax > 0 {
-		ctx, cancel = context.WithDeadline(ctx, start.Add(time.Duration(req.TMax)*time.Millisecond))
+		ctx, cancel = context.WithDeadline(ctx, ao.StartTime.Add(time.Duration(req.TMax)*time.Millisecond))
 	} else {
-		ctx, cancel = context.WithDeadline(ctx, start.Add(time.Duration(defaultAmpRequestTimeoutMillis)*time.Millisecond))
+		ctx, cancel = context.WithDeadline(ctx, ao.StartTime.Add(time.Duration(defaultAmpRequestTimeoutMillis)*time.Millisecond))
 	}
 	defer cancel()
 
@@ -188,6 +187,7 @@ func (deps *endpointDeps) AmpAuction(w http.ResponseWriter, r *http.Request, _ h
 		Account:      *account,
 		UserSyncs:    usersyncs,
 		RequestType:  labels.RType,
+		StartTime:    ao.StartTime,
 		LegacyLabels: labels,
 	}
 

endpoints/openrtb2/auction.go

@@ -101,15 +101,15 @@ func (deps *endpointDeps) Auction(w http.ResponseWriter, r *http.Request, _ http
 	ao := analytics.AuctionObject{
 		Status: http.StatusOK,
 		Errors: make([]error, 0),
+		// Prebid Server interprets request.tmax to be the maximum amount of time that a caller is willing
+		// to wait for bids. However, tmax may be defined in the Stored Request data.
+		//
+		// If so, then the trip to the backend might use a significant amount of this time.
+		// We can respect timeouts more accurately if we note the *real* start time, and use it
+		// to compute the auction timeout.
+		StartTime: time.Now(),
 	}
 
-	// Prebid Server interprets request.tmax to be the maximum amount of time that a caller is willing
-	// to wait for bids. However, tmax may be defined in the Stored Request data.
-	//
-	// If so, then the trip to the backend might use a significant amount of this time.
-	// We can respect timeouts more accurately if we note the *real* start time, and use it
-	// to compute the auction timeout.
-	start := time.Now()
 	labels := pbsmetrics.Labels{
 		Source:        pbsmetrics.DemandUnknown,
 		RType:         pbsmetrics.ReqTypeORTB2Web,
@@ -120,7 +120,7 @@ func (deps *endpointDeps) Auction(w http.ResponseWriter, r *http.Request, _ http
 	}
 	defer func() {
 		deps.metricsEngine.RecordRequest(labels)
-		deps.metricsEngine.RecordRequestTime(labels, time.Since(start))
+		deps.metricsEngine.RecordRequestTime(labels, time.Since(ao.StartTime))
 		deps.analytics.LogAuctionObject(&ao)
 	}()
 
@@ -135,7 +135,7 @@ func (deps *endpointDeps) Auction(w http.ResponseWriter, r *http.Request, _ http
 	timeout := deps.cfg.AuctionTimeouts.LimitAuctionTimeout(time.Duration(req.TMax) * time.Millisecond)
 	if timeout > 0 {
 		var cancel context.CancelFunc
-		ctx, cancel = context.WithDeadline(ctx, start.Add(timeout))
+		ctx, cancel = context.WithDeadline(ctx, ao.StartTime.Add(timeout))
 		defer cancel()
 	}
 
@@ -167,6 +167,7 @@ func (deps *endpointDeps) Auction(w http.ResponseWriter, r *http.Request, _ http
 		Account:      *account,
 		UserSyncs:    usersyncs,
 		RequestType:  labels.RType,
+		StartTime:    ao.StartTime,
 		LegacyLabels: labels,
 	}
 

endpoints/openrtb2/video_auction.go

@@ -95,11 +95,11 @@ func NewVideoEndpoint(ex exchange.Exchange, validator openrtb_ext.BidderParamVal
 func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Request, _ httprouter.Params) {
 
 	vo := analytics.VideoObject{
-		Status: http.StatusOK,
-		Errors: make([]error, 0),
+		Status:    http.StatusOK,
+		Errors:    make([]error, 0),
+		StartTime: time.Now(),
 	}
 
-	start := time.Now()
 	labels := pbsmetrics.Labels{
 		Source:        pbsmetrics.DemandUnknown,
 		RType:         pbsmetrics.ReqTypeVideo,
@@ -129,7 +129,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re
 			}
 		}
 		deps.metricsEngine.RecordRequest(labels)
-		deps.metricsEngine.RecordRequestTime(labels, time.Since(start))
+		deps.metricsEngine.RecordRequestTime(labels, time.Since(vo.StartTime))
 		deps.analytics.LogVideoObject(&vo)
 	}()
 
@@ -236,7 +236,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re
 	timeout := deps.cfg.AuctionTimeouts.LimitAuctionTimeout(time.Duration(bidReq.TMax) * time.Millisecond)
 	if timeout > 0 {
 		var cancel context.CancelFunc
-		ctx, cancel = context.WithDeadline(ctx, start.Add(timeout))
+		ctx, cancel = context.WithDeadline(ctx, vo.StartTime.Add(timeout))
 		defer cancel()
 	}
 
@@ -266,6 +266,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re
 		Account:      *account,
 		UserSyncs:    usersyncs,
 		RequestType:  labels.RType,
+		StartTime:    vo.StartTime,
 		LegacyLabels: labels,
 	}
 

exchange/exchange.go

@@ -102,6 +102,7 @@ type AuctionRequest struct {
 	Account     config.Account
 	UserSyncs   IdFetcher
 	RequestType pbsmetrics.RequestType
+	StartTime   time.Time
 
 	// LegacyLabels is included here for temporary compatability with cleanOpenRTBRequests
 	// in HoldAuction until we get to factoring it away. Do not use for anything new.
@@ -188,7 +189,7 @@ func (e *exchange) HoldAuction(ctx context.Context, r AuctionRequest, debugLog *
 		}
 	}
 
-	bidResponseExt := e.makeExtBidResponse(adapterBids, adapterExtra, r.BidRequest, debugInfo, errs)
+	bidResponseExt := e.makeExtBidResponse(adapterBids, adapterExtra, r, debugInfo, errs)
 
 	// Ensure caching errors are added in case auc.doCache was called and errors were returned
 	if len(cacheErrs) > 0 {
@@ -714,7 +715,8 @@ func getPrimaryAdServer(adServerId int) (string, error) {
 }
 
 // Extract all the data from the SeatBids and build the ExtBidResponse
-func (e *exchange) makeExtBidResponse(adapterBids map[openrtb_ext.BidderName]*pbsOrtbSeatBid, adapterExtra map[openrtb_ext.BidderName]*seatResponseExtra, req *openrtb.BidRequest, debugInfo bool, errList []error) *openrtb_ext.ExtBidResponse {
+func (e *exchange) makeExtBidResponse(adapterBids map[openrtb_ext.BidderName]*pbsOrtbSeatBid, adapterExtra map[openrtb_ext.BidderName]*seatResponseExtra, r AuctionRequest, debugInfo bool, errList []error) *openrtb_ext.ExtBidResponse {
+	req := r.BidRequest
 	bidResponseExt := &openrtb_ext.ExtBidResponse{
 		Errors:               make(map[openrtb_ext.BidderName][]openrtb_ext.ExtBidderError, len(adapterBids)),
 		ResponseTimeMillis:   make(map[openrtb_ext.BidderName]int, len(adapterBids)),
@@ -726,6 +728,12 @@ func (e *exchange) makeExtBidResponse(adapterBids map[openrtb_ext.BidderName]*pb
 			ResolvedRequest: req,
 		}
 	}
+	if !r.StartTime.IsZero() {
+		// auctiontimestamp is the only response.ext.prebid attribute we may emit
+		bidResponseExt.Prebid = &openrtb_ext.ExtResponsePrebid{
+			AuctionTimestamp: r.StartTime.UnixNano() / 1e+6,
+		}
+	}
 
 	for bidderName, responseExtra := range adapterExtra {
 

exchange/exchange_test.go

@@ -252,6 +252,7 @@ func TestDebugBehaviour(t *testing.T) {
 			BidRequest: bidRequest,
 			Account:    config.Account{},
 			UserSyncs:  &emptyUsersync{},
+			StartTime:  time.Now(),
 		}
 
 		// Run test
@@ -265,6 +266,10 @@ func TestDebugBehaviour(t *testing.T) {
 		err = json.Unmarshal(outBidResponse.Ext, actualExt)
 		assert.NoErrorf(t, err, "%s. \"ext\" JSON field could not be unmarshaled. err: \"%v\" \n outBidResponse.Ext: \"%s\" \n", test.desc, err, outBidResponse.Ext)
 
+		assert.NotEmpty(t, actualExt.Prebid, "%s. ext.prebid should not be empty")
+		assert.NotEmpty(t, actualExt.Prebid.AuctionTimestamp, "%s. ext.prebid.auctiontimestamp should not be empty when AuctionRequest.StartTime is set")
+		assert.Equal(t, auctionRequest.StartTime.UnixNano()/1e+6, actualExt.Prebid.AuctionTimestamp, "%s. ext.prebid.auctiontimestamp has incorrect value")
+
 		if test.out.debugInfoIncluded {
 			assert.NotNilf(t, actualExt, "%s. ext.debug field is expected to be included in this outBidResponse.Ext and not be nil.  outBidResponse.Ext.Debug = %v \n", test.desc, actualExt.Debug)
 

openrtb_ext/response.go

@@ -17,6 +17,8 @@ type ExtBidResponse struct {
 	RequestTimeoutMillis int64 `json:"tmaxrequest,omitempty"`
 	// ResponseUserSync defines the contract for bidresponse.ext.usersync
 	Usersync map[BidderName]*ExtResponseSyncData `json:"usersync,omitempty"`
+	// Prebid defines the contract for bidresponse.ext.prebid
+	Prebid *ExtResponsePrebid `json:"prebid,omitempty"`
 }
 
 // ExtResponseDebug defines the contract for bidresponse.ext.debug
@@ -34,6 +36,11 @@ type ExtResponseSyncData struct {
 	Syncs []*ExtUserSync `json:"syncs"`
 }
 
+// ExtResponsePrebid defines the contract for bidresponse.ext.prebid
+type ExtResponsePrebid struct {
+	AuctionTimestamp int64 `json:"auctiontimestamp,omitempty"`
+}
+
 // ExtUserSync defines the contract for bidresponse.ext.usersync.{bidder}.syncs[i]
 type ExtUserSync struct {
 	Url  string       `json:"url"`