Add custom JSON req/resp data to the analytics logging… (#1145)

* Add custom JSON req/resp data to the analytics logging for the /openrtb2/video endpoint.

* Add calls in unit tests to cover logging and jsonify of video object.

analytics/config/config.go

@@ -29,6 +29,12 @@ func (ea enabledAnalytics) LogAuctionObject(ao *analytics.AuctionObject) {
 	}
 }
 
+func (ea enabledAnalytics) LogVideoObject(vo *analytics.VideoObject) {
+	for _, module := range ea {
+		module.LogVideoObject(vo)
+	}
+}
+
 func (ea enabledAnalytics) LogCookieSyncObject(cso *analytics.CookieSyncObject) {
 	for _, module := range ea {
 		module.LogCookieSyncObject(cso)

analytics/config/config_test.go

@@ -45,6 +45,11 @@ func TestSampleModule(t *testing.T) {
 	if count != 4 {
 		t.Errorf("PBSAnalyticsModule failed at LogAmpObject")
 	}
+
+	am.LogVideoObject(&analytics.VideoObject{})
+	if count != 5 {
+		t.Errorf("PBSAnalyticsModule failed at LogVideoObject")
+	}
 }
 
 type sampleModule struct {
@@ -53,6 +58,8 @@ type sampleModule struct {
 
 func (m *sampleModule) LogAuctionObject(ao *analytics.AuctionObject) { *m.count++ }
 
+func (m *sampleModule) LogVideoObject(vo *analytics.VideoObject) { *m.count++ }
+
 func (m *sampleModule) LogCookieSyncObject(cso *analytics.CookieSyncObject) { *m.count++ }
 
 func (m *sampleModule) LogSetUIDObject(so *analytics.SetUIDObject) { *m.count++ }

analytics/core.go

@@ -2,6 +2,7 @@ package analytics
 
 import (
 	"github.com/mxmCherry/openrtb"
+	"github.com/prebid/prebid-server/openrtb_ext"
 	"github.com/prebid/prebid-server/usersync"
 )
 
@@ -15,6 +16,7 @@ import (
 
 type PBSAnalyticsModule interface {
 	LogAuctionObject(*AuctionObject)
+	LogVideoObject(*VideoObject)
 	LogCookieSyncObject(*CookieSyncObject)
 	LogSetUIDObject(*SetUIDObject)
 	LogAmpObject(*AmpObject)
@@ -38,6 +40,16 @@ type AmpObject struct {
 	Origin             string
 }
 
+//Loggable object of a transaction at /openrtb2/video endpoint
+type VideoObject struct {
+	Status        int
+	Errors        []error
+	Request       *openrtb.BidRequest
+	Response      *openrtb.BidResponse
+	VideoRequest  *openrtb_ext.BidRequestVideo
+	VideoResponse *openrtb_ext.BidResponseVideo
+}
+
 //Loggable object of a transaction at /setuid
 type SetUIDObject struct {
 	Status  int

analytics/filesystem/file_module.go

@@ -14,6 +14,7 @@ type RequestType string
 const (
 	COOKIE_SYNC RequestType = "/cookie_sync"
 	AUCTION     RequestType = "/openrtb2/auction"
+	VIDEO       RequestType = "/openrtb2/video"
 	SETUID      RequestType = "/set_uid"
 	AMP         RequestType = "/openrtb2/amp"
 )
@@ -32,6 +33,15 @@ func (f *FileLogger) LogAuctionObject(ao *analytics.AuctionObject) {
 	f.Logger.Flush()
 }
 
+//Writes VideoObject to file
+func (f *FileLogger) LogVideoObject(vo *analytics.VideoObject) {
+	//Code to parse the object and log in a way required
+	var b bytes.Buffer
+	b.WriteString(jsonifyVideoObject(vo))
+	f.Logger.Debug(b.String())
+	f.Logger.Flush()
+}
+
 //Logs SetUIDObject to file
 func (f *FileLogger) LogSetUIDObject(so *analytics.SetUIDObject) {
 	//Code to parse the object and log in a way required
@@ -98,6 +108,23 @@ func jsonifyAuctionObject(ao *analytics.AuctionObject) string {
 	}
 }
 
+func jsonifyVideoObject(vo *analytics.VideoObject) string {
+	type alias analytics.VideoObject
+	b, err := json.Marshal(&struct {
+		Type RequestType `json:"type"`
+		*alias
+	}{
+		Type:  VIDEO,
+		alias: (*alias)(vo),
+	})
+
+	if err == nil {
+		return string(b)
+	} else {
+		return fmt.Sprintf("Transactional Logs Error: Video object badly formed %v", err)
+	}
+}
+
 func jsonifyCookieSync(cso *analytics.CookieSyncObject) string {
 	type alias analytics.CookieSyncObject
 

analytics/filesystem/file_module_test.go

@@ -34,6 +34,15 @@ func TestAuctionObject_ToJson(t *testing.T) {
 	}
 }
 
+func TestVideoObject_ToJson(t *testing.T) {
+	vo := &analytics.VideoObject{
+		Status: http.StatusOK,
+	}
+	if voJson := jsonifyVideoObject(vo); strings.Contains(voJson, "Transactional Logs Error") {
+		t.Fatalf("AuctionObject failed to convert to json")
+	}
+}
+
 func TestSetUIDObject_ToJson(t *testing.T) {
 	so := &analytics.SetUIDObject{
 		Status: http.StatusOK,
@@ -64,6 +73,7 @@ func TestFileLogger_LogObjects(t *testing.T) {
 	defer os.RemoveAll(TEST_DIR)
 	if fl, err := NewFileLogger(TEST_DIR + "//test"); err == nil {
 		fl.LogAuctionObject(&analytics.AuctionObject{})
+		fl.LogVideoObject(&analytics.VideoObject{})
 		fl.LogAmpObject(&analytics.AmpObject{})
 		fl.LogSetUIDObject(&analytics.SetUIDObject{})
 		fl.LogCookieSyncObject(&analytics.CookieSyncObject{})

endpoints/openrtb2/video_auction.go

@@ -65,7 +65,7 @@ func NewVideoEndpoint(ex exchange.Exchange, validator openrtb_ext.BidderParamVal
 */
 func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Request, _ httprouter.Params) {
 
-	ao := analytics.AuctionObject{
+	vo := analytics.VideoObject{
 		Status: http.StatusOK,
 		Errors: make([]error, 0),
 	}
@@ -82,7 +82,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re
 	defer func() {
 		deps.metricsEngine.RecordRequest(labels)
 		deps.metricsEngine.RecordRequestTime(labels, time.Since(start))
-		deps.analytics.LogAuctionObject(&ao)
+		deps.analytics.LogVideoObject(&vo)
 	}()
 
 	lr := &io.LimitedReader{
@@ -91,7 +91,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re
 	}
 	requestJson, err := ioutil.ReadAll(lr)
 	if err != nil {
-		handleError(&labels, w, []error{err}, &ao)
+		handleError(&labels, w, []error{err}, &vo)
 		return
 	}
 
@@ -102,35 +102,37 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re
 
 	if err != nil {
 		if deps.cfg.VideoStoredRequestRequired {
-			handleError(&labels, w, []error{err}, &ao)
+			handleError(&labels, w, []error{err}, &vo)
 			return
 		}
 	} else {
 		storedRequest, errs := deps.loadStoredVideoRequest(context.Background(), storedRequestId)
 		if len(errs) > 0 {
-			handleError(&labels, w, errs, &ao)
+			handleError(&labels, w, errs, &vo)
 			return
 		}
 
 		//merge incoming req with stored video req
 		resolvedRequest, err = jsonpatch.MergePatch(storedRequest, requestJson)
 		if err != nil {
-			handleError(&labels, w, []error{err}, &ao)
+			handleError(&labels, w, []error{err}, &vo)
 			return
 		}
 	}
 	//unmarshal and validate combined result
 	videoBidReq, errL, podErrors := deps.parseVideoRequest(resolvedRequest)
 	if len(errL) > 0 {
-		handleError(&labels, w, errL, &ao)
+		handleError(&labels, w, errL, &vo)
 		return
 	}
 
+	vo.VideoRequest = videoBidReq
+
 	var bidReq = &openrtb.BidRequest{}
 	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}, &ao)
+			handleError(&labels, w, []error{err}, &vo)
 			return
 		}
 	}
@@ -154,7 +156,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, &ao)
+		handleError(&labels, w, errL, &vo)
 		return
 	}
 
@@ -166,7 +168,7 @@ func (deps *endpointDeps) VideoAuctionEndpoint(w http.ResponseWriter, r *http.Re
 
 	errL = deps.validateRequest(bidReq)
 	if len(errL) > 0 {
-		handleError(&labels, w, errL, &ao)
+		handleError(&labels, w, errL, &vo)
 		return
 	}
 
@@ -194,35 +196,37 @@ 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, &ao)
+		handleError(&labels, w, errL, &vo)
 		return
 	}
 	//execute auction logic
 	response, err := deps.ex.HoldAuction(ctx, bidReq, usersyncs, labels, &deps.categories)
-	ao.Request = bidReq
-	ao.Response = response
+	vo.Request = bidReq
+	vo.Response = response
 	if err != nil {
 		errL := []error{err}
-		handleError(&labels, w, errL, &ao)
+		handleError(&labels, w, errL, &vo)
 		return
 	}
 
 	//build simplified response
 	bidResp, err := buildVideoResponse(response, podErrors)
 	if err != nil {
 		errL := []error{err}
-		handleError(&labels, w, errL, &ao)
+		handleError(&labels, w, errL, &vo)
 		return
 	}
 	if bidReq.Test == 1 {
 		bidResp.Ext = response.Ext
 	}
 
+	vo.VideoResponse = bidResp
+
 	resp, err := json.Marshal(bidResp)
 	//resp, err := json.Marshal(response)
 	if err != nil {
 		errL := []error{err}
-		handleError(&labels, w, errL, &ao)
+		handleError(&labels, w, errL, &vo)
 		return
 	}
 
@@ -238,7 +242,7 @@ func cleanupVideoBidRequest(videoReq *openrtb_ext.BidRequestVideo, podErrors []P
 	return videoReq
 }
 
-func handleError(labels *pbsmetrics.Labels, w http.ResponseWriter, errL []error, ao *analytics.AuctionObject) {
+func handleError(labels *pbsmetrics.Labels, w http.ResponseWriter, errL []error, vo *analytics.VideoObject) {
 	labels.RequestStatus = pbsmetrics.RequestStatusErr
 	var errors string
 	var status int = http.StatusInternalServerError
@@ -256,10 +260,10 @@ func handleError(labels *pbsmetrics.Labels, w http.ResponseWriter, errL []error,
 		errors = fmt.Sprintf("%s %s", errors, er.Error())
 	}
 	w.WriteHeader(status)
-	ao.Status = status
+	vo.Status = status
 	fmt.Fprintf(w, "Critical error while running the video endpoint: %v", errors)
 	glog.Errorf("/openrtb2/video Critical error: %v", errors)
-	ao.Errors = append(ao.Errors, errL...)
+	vo.Errors = append(vo.Errors, errL...)
 }
 
 func (deps *endpointDeps) createImpressions(videoReq *openrtb_ext.BidRequestVideo, podErrors []PodError) ([]openrtb.Imp, []PodError) {

endpoints/openrtb2/video_auction_test.go

@@ -650,7 +650,7 @@ func TestMergeOpenRTBToVideoRequest(t *testing.T) {
 }
 
 func TestHandleError(t *testing.T) {
-	ao := analytics.AuctionObject{
+	vo := analytics.VideoObject{
 		Status: 200,
 		Errors: make([]error, 0),
 	}
@@ -667,14 +667,14 @@ 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}, &ao)
+	handleError(&labels, recorder, []error{err1, err2}, &vo)
 
 	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, ao.Status, "AnalyticsObject should have error status")
-	assert.Equal(t, 2, len(ao.Errors), "New errors should be appended to AnalyticsObject Errors")
-	assert.Equal(t, "Error for testing handleError 1", ao.Errors[0].Error(), "Error in AnalyticsObject should have test error message for first error")
-	assert.Equal(t, "Error for testing handleError 2", ao.Errors[1].Error(), "Error in AnalyticsObject should have test error message for second error")
+	assert.Equal(t, 500, vo.Status, "Analytics object should have error status")
+	assert.Equal(t, 2, len(vo.Errors), "New errors 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")
 }
 
 func TestHandleErrorMetrics(t *testing.T) {
@@ -692,11 +692,11 @@ func TestHandleErrorMetrics(t *testing.T) {
 
 	assert.Equal(t, int64(0), met.RequestStatuses[pbsmetrics.ReqTypeVideo][pbsmetrics.RequestStatusOK].Count(), "OK requests count should be 0")
 	assert.Equal(t, int64(1), met.RequestStatuses[pbsmetrics.ReqTypeVideo][pbsmetrics.RequestStatusErr].Count(), "Error requests count should be 1")
-	assert.Equal(t, 1, len(mod.auctionObjects), "Mock AnalyticsModule should have 1 AuctionObject")
-	assert.Equal(t, 500, mod.auctionObjects[0].Status, "AnalyticsObject should have 500 status")
-	assert.Equal(t, 2, len(mod.auctionObjects[0].Errors), "AnalyticsObject should have Errors length of 2")
-	assert.Equal(t, "request missing required field: PodConfig.DurationRangeSec", mod.auctionObjects[0].Errors[0].Error(), "First error in AnalyticsObject should have message regarding DurationRangeSec")
-	assert.Equal(t, "request missing required field: PodConfig.Pods", mod.auctionObjects[0].Errors[1].Error(), "Second error in AnalyticsObject should have message regarding Pods")
+	assert.Equal(t, 1, len(mod.videoObjects), "Mock AnalyticsModule should have 1 AuctionObject")
+	assert.Equal(t, 500, mod.videoObjects[0].Status, "AnalyticsObject should have 500 status")
+	assert.Equal(t, 2, len(mod.videoObjects[0].Errors), "AnalyticsObject should have Errors length of 2")
+	assert.Equal(t, "request missing required field: PodConfig.DurationRangeSec", mod.videoObjects[0].Errors[0].Error(), "First error in AnalyticsObject should have message regarding DurationRangeSec")
+	assert.Equal(t, "request missing required field: PodConfig.Pods", mod.videoObjects[0].Errors[1].Error(), "Second error in AnalyticsObject should have message regarding Pods")
 }
 
 func mockDepsWithMetrics(t *testing.T, ex *mockExchangeVideo) (*endpointDeps, *pbsmetrics.Metrics, *mockAnalyticsModule) {
@@ -722,12 +722,17 @@ func mockDepsWithMetrics(t *testing.T, ex *mockExchangeVideo) (*endpointDeps, *p
 
 type mockAnalyticsModule struct {
 	auctionObjects []*analytics.AuctionObject
+	videoObjects   []*analytics.VideoObject
 }
 
 func (m *mockAnalyticsModule) LogAuctionObject(ao *analytics.AuctionObject) {
 	m.auctionObjects = append(m.auctionObjects, ao)
 }
 
+func (m *mockAnalyticsModule) LogVideoObject(vo *analytics.VideoObject) {
+	m.videoObjects = append(m.videoObjects, vo)
+}
+
 func (m *mockAnalyticsModule) LogCookieSyncObject(cso *analytics.CookieSyncObject) { return }
 
 func (m *mockAnalyticsModule) LogSetUIDObject(so *analytics.SetUIDObject) { return }