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

Extra logging for timeout notifications #1349

Merged
merged 3 commits into from
Jun 17, 2020
Merged

Extra logging for timeout notifications #1349

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
4e7c2de
Extra logging for timeout notifications
hhhjort Jun 11, 2020
c6620cc
More granular logging
hhhjort Jun 15, 2020
fb7e8ca
A basic test
hhhjort Jun 15, 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
13 changes: 13 additions & 0 deletions exchange/bidder.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -389,7 +389,20 @@ func (bidder *bidderAdapter) doTimeoutNotification(timeoutBidder adapters.Timeou
}
} else {
bidder.me.RecordTimeoutNotice(false)
if bidder.DebugConfig.TimeoutNotification.Log {
msg := fmt.Sprintf("TimeoutNotification: Failed to make timeout request: method(%s), uri(%s), error(%s)", toReq.Method, toReq.Uri, err.Error())
util.LogRandomSample(msg, glog.Warningf, bidder.DebugConfig.TimeoutNotification.SamplingRate)
}
}
} else if bidder.DebugConfig.TimeoutNotification.Log {
reqJSON, err := json.Marshal(req)
var msg string
if err == nil {
msg = fmt.Sprintf("TimeoutNotification: Failed to generate timeout request: error(%s), bidder request(%s)", errL[0].Error(), string(reqJSON))
} else {
msg = fmt.Sprintf("TimeoutNotification: Failed to generate timeout request: error(%s), bidder request marshal failed(%s)", errL[0].Error(), err.Error())
}
util.LogRandomSample(msg, glog.Warningf, bidder.DebugConfig.TimeoutNotification.SamplingRate)
}

}
Expand Down
74 changes: 74 additions & 0 deletions exchange/bidder_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1229,6 +1229,64 @@ func TestSetAssetTypes(t *testing.T) {
}
}

func TestTimeoutNotificationOff(t *testing.T) {
respBody := "{\"bid\":false}"
respStatus := 200
server := httptest.NewServer(mockHandler(respStatus, "getBody", respBody))
defer server.Close()

bidderImpl := &notifingBidder{
notiRequest: adapters.RequestData{
Method: "GET",
Uri: server.URL + "/notify/me",
Body: nil,
Headers: http.Header{},
},
}
bidder := &bidderAdapter{
Bidder: bidderImpl,
Client: server.Client(),
DebugConfig: config.Debug{},
me: &metricsConfig.DummyMetricsEngine{},
}
if tb, ok := bidder.Bidder.(adapters.TimeoutBidder); !ok {
t.Error("Failed to cast bidder to a TimeoutBidder")
} else {
bidder.doTimeoutNotification(tb, &adapters.RequestData{})
}
}

func TestTimeoutNotificationOn(t *testing.T) {
respBody := "{\"bid\":false}"
respStatus := 200
server := httptest.NewServer(mockHandler(respStatus, "getBody", respBody))
defer server.Close()

bidderImpl := &notifingBidder{
notiRequest: adapters.RequestData{
Method: "GET",
Uri: server.URL + "/notify/me",
Body: nil,
Headers: http.Header{},
},
}
bidder := &bidderAdapter{
Bidder: bidderImpl,
Client: server.Client(),
DebugConfig: config.Debug{
TimeoutNotification: config.TimeoutNotification{
Log: true,
},
},
me: &metricsConfig.DummyMetricsEngine{},
}
if tb, ok := bidder.Bidder.(adapters.TimeoutBidder); !ok {
t.Error("Failed to cast bidder to a TimeoutBidder")
} else {
bidder.doTimeoutNotification(tb, &adapters.RequestData{})
Copy link
Contributor

Choose a reason for hiding this comment

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

The setup is good. There's no assertion after the call to doTimeoutNotification. @bsardo encountered the same trouble in the story he's working on. I don't see a way to make it better now, but we should look to wrap the logger instead of calling the static glog directly so we can inject and inspect log entries.. as well as provide a mechanism to swap out to logrus in the future (via a config option).

}
}

type goodSingleBidder struct {
bidRequest *openrtb.BidRequest
httpRequest *adapters.RequestData
Expand Down Expand Up @@ -1302,3 +1360,19 @@ func (bidder *bidRejector) MakeBids(internalRequest *openrtb.BidRequest, externa
bidder.httpResponse = response
return nil, []error{errors.New("Can't make a response.")}
}

type notifingBidder struct {
notiRequest adapters.RequestData
}

func (bidder *notifingBidder) MakeRequests(request *openrtb.BidRequest, reqInfo *adapters.ExtraRequestInfo) ([]*adapters.RequestData, []error) {
return nil, nil
}

func (bidder *notifingBidder) MakeBids(internalRequest *openrtb.BidRequest, externalRequest *adapters.RequestData, response *adapters.ResponseData) (*adapters.BidderResponse, []error) {
return nil, nil
}

func (bidder *notifingBidder) MakeTimeoutNotification(req *adapters.RequestData) (*adapters.RequestData, []error) {
return &bidder.notiRequest, nil
}