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

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

Merged
merged 2 commits into from
Jan 10, 2020
Merged

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

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
275e8c8
Add custom JSON req/resp data to the analytics logging for the /openr…
jmaynardxandr Dec 13, 2019
03648bb
Add calls in unit tests to cover logging and jsonify of video object.
jmaynardxandr Dec 13, 2019
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
6 changes: 6 additions & 0 deletions analytics/config/config.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)
}
}

Copy link
Contributor

Choose a reason for hiding this comment

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

image
Newly added function is not being covered by test cases

func (ea enabledAnalytics) LogCookieSyncObject(cso *analytics.CookieSyncObject) {
for _, module := range ea {
module.LogCookieSyncObject(cso)
Expand Down
7 changes: 7 additions & 0 deletions analytics/config/config_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand All @@ -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++ }
Expand Down
12 changes: 12 additions & 0 deletions analytics/core.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@ package analytics

import (
"github.com/mxmCherry/openrtb"
"github.com/prebid/prebid-server/openrtb_ext"
"github.com/prebid/prebid-server/usersync"
)

Expand All @@ -15,6 +16,7 @@ import (

type PBSAnalyticsModule interface {
LogAuctionObject(*AuctionObject)
LogVideoObject(*VideoObject)
LogCookieSyncObject(*CookieSyncObject)
LogSetUIDObject(*SetUIDObject)
LogAmpObject(*AmpObject)
Expand All @@ -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
Expand Down
27 changes: 27 additions & 0 deletions analytics/filesystem/file_module.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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"
)
Expand All @@ -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())
Copy link
Contributor

Choose a reason for hiding this comment

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

I'm probably not understanding the whole context but if jsonifyVideoObject finds an error, will just flush to the log with a DEBUG flag?

"2019/12/18 14:16:03 DEBUG Transactional Logs Error: Auction object badly formed JSON_MARSHALL_ERR_MESSAGE"

Is this what we want? Don't we want to log to the Error level?

Copy link
Contributor Author

@jmaynardxandr jmaynardxandr Jan 2, 2020 •
edited
Loading

Choose a reason for hiding this comment

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

This function is intended to log the video object at the debug level, but if there is an error in that process then yes I agree it would be better to log that as an error instead. The point of this PR however is really just to add the custom JSON request and response used by the /video endpoint to the analytics logging, so I'd prefer to leave improvements to the existing testing/logging as a separate issue. (note while this specific function to log the video object is technically new code, I say "existing" here because it's basically just a copy-&-paste of how all the other objects are being logged).

f.Logger.Flush()
}

Copy link
Contributor

Choose a reason for hiding this comment

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

image
Again, newly created function seems to not be covered by the test cases in contrast with other functions in the same file

//Logs SetUIDObject to file
func (f *FileLogger) LogSetUIDObject(so *analytics.SetUIDObject) {
//Code to parse the object and log in a way required
Expand Down Expand Up @@ -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)
}
}

Copy link
Contributor

Choose a reason for hiding this comment

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

image
there seems to not be test cases for jsonifyVideoObject either. What if the parameter is nil? Are we ok with a JSON object with a nil field? Do we need to check for nil? I realized this is a local function but if we want to extend in the future, corner cases wouldn't hurt.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Yes good point Gus, I added some calls to test the video endpoint logging and jsonify also in the new commit. Regarding checking for nil fields in jsonifyVideoObject I think it will be ok because if a field is nil it will show up in the JSON with a null value, which the person evaluating the log file should intuitively associate with a nil value in Go. Thanks for the feedback.

func jsonifyCookieSync(cso *analytics.CookieSyncObject) string {
type alias analytics.CookieSyncObject

Expand Down
10 changes: 10 additions & 0 deletions analytics/filesystem/file_module_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -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{})
Copy link
Contributor

Choose a reason for hiding this comment

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

In order to have a more comprehensive test do you think it won't be much of a hassle to compare the log file at the end of this test? Maybe the the SameFile(fi1, fi2 FileInfo) method from the OS package or even asserting against bytes.Compare could suffice. What do you think?

Copy link
Collaborator

Choose a reason for hiding this comment

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

Comparing log files might be tricky, if logger is including time stamps. you will have to craft some regex's to test the output. Or make your own version of NewFileLogger() that creates a non-timestamped logger to generate data.

fl.LogSetUIDObject(&analytics.SetUIDObject{})
fl.LogCookieSyncObject(&analytics.CookieSyncObject{})
Expand Down
42 changes: 23 additions & 19 deletions endpoints/openrtb2/video_auction.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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),
}
Expand All @@ -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{
Expand All @@ -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
}

Expand All @@ -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
}
}
Expand All @@ -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
}

Expand All @@ -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
}

Expand Down Expand Up @@ -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
}

Expand All @@ -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
Expand All @@ -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) {
Expand Down
27 changes: 16 additions & 11 deletions endpoints/openrtb2/video_auction_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -644,7 +644,7 @@ func TestMergeOpenRTBToVideoRequest(t *testing.T) {
}

func TestHandleError(t *testing.T) {
ao := analytics.AuctionObject{
vo := analytics.VideoObject{
Status: 200,
Errors: make([]error, 0),
}
Expand All @@ -661,14 +661,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) {
Expand All @@ -686,11 +686,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) {
Expand All @@ -716,12 +716,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 }
Expand Down