-
Notifications
You must be signed in to change notification settings - Fork 731
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.
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
Timeout notification monitoring and debugging #1322
Changes from 5 commits
77f0302
0c90007
811d885
28a9990
87f8846
e584ade
ff02353
6567f29
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
Original file line number | Diff line number | Diff line change |
---|---|---|
|
@@ -66,6 +66,8 @@ type Configuration struct { | |
PemCertsFile string `mapstructure:"certificates_file"` | ||
// Custom headers to handle request timeouts from queueing infrastructure | ||
RequestTimeoutHeaders RequestTimeoutHeaders `mapstructure:"request_timeout_headers"` | ||
// Debug/logging flags go here | ||
Debug Debug `mapstructure:"debug"` | ||
} | ||
|
||
const MIN_COOKIE_SIZE_BYTES = 500 | ||
|
@@ -428,6 +430,30 @@ type DefReqFiles struct { | |
FileName string `mapstructure:"name"` | ||
} | ||
|
||
type Debug struct { | ||
TimeoutNotification TimeoutNotification `mapstructure:"timeout_notification"` | ||
} | ||
|
||
func (cfg *Debug) validate(errs configErrors) configErrors { | ||
return cfg.TimeoutNotification.validate(errs) | ||
} | ||
|
||
type TimeoutNotification struct { | ||
// Log timeout notifications in the application log | ||
Log bool `mapstructure:"log"` | ||
// Fraction of notifications to log | ||
Sampling float32 `mapstructure:"sampling"` | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Nitpick: Consider renaming to There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Do you not agree with this one? |
||
// Only log failures | ||
FailOnly bool `mapstructure:"fail_only"` | ||
} | ||
|
||
func (cfg *TimeoutNotification) validate(errs configErrors) configErrors { | ||
if cfg.Sampling < 0.0 || cfg.Sampling > 1.0 { | ||
errs = append(errs, fmt.Errorf("debug.timeout_notification.sampling must be positive and not greater than 1.0. Got %f", cfg.Sampling)) | ||
} | ||
return errs | ||
} | ||
|
||
// New uses viper to get our server configurations. | ||
func New(v *viper.Viper) (*Configuration, error) { | ||
var c Configuration | ||
|
@@ -785,6 +811,10 @@ func SetupViper(v *viper.Viper, filename string) { | |
v.SetDefault("request_timeout_headers.request_time_in_queue", "") | ||
v.SetDefault("request_timeout_headers.request_timeout_in_queue", "") | ||
|
||
v.SetDefault("debug.timeout_notification.log", false) | ||
v.SetDefault("debug.timeout_notification.sampling", 0.0) | ||
v.SetDefault("debug.timeout_notification.fail_only", false) | ||
|
||
// Set environment variable support: | ||
v.SetEnvKeyReplacer(strings.NewReplacer(".", "_")) | ||
v.SetEnvPrefix("PBS") | ||
|
Original file line number | Diff line number | Diff line change |
---|---|---|
@@ -0,0 +1,24 @@ | ||
package util | ||
|
||
import ( | ||
"math/rand" | ||
) | ||
|
||
type logMsg func(string, ...interface{}) | ||
|
||
type randomGenerator func() float32 | ||
|
||
// LogRandomSample will log a randam sample of the messages it is sent, based on the chance to log | ||
// chance = 1.0 => always log, | ||
// chance = 0.0 => never log | ||
func LogRandomSample(msg string, logger logMsg, chance float32) { | ||
logRandomSampleImpl(msg, logger, chance, rand.Float32) | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Locally I added the test that follows to
Result
|
||
} | ||
|
||
func logRandomSampleImpl(msg string, logger logMsg, chance float32, randGenerator randomGenerator) { | ||
if chance < 1.0 && randGenerator() > chance { | ||
// this is the chance we don't log anything | ||
return | ||
} | ||
logger(msg) | ||
} |
Original file line number | Diff line number | Diff line change |
---|---|---|
@@ -0,0 +1,31 @@ | ||
package util | ||
|
||
import ( | ||
"bytes" | ||
"fmt" | ||
"math/rand" | ||
"testing" | ||
|
||
"github.com/stretchr/testify/assert" | ||
) | ||
|
||
var expected string = `This is test line 2 | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Please move into the |
||
This is test line 3 | ||
` | ||
|
||
func TestLogRandomSample(t *testing.T) { | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Now that we have extracted LogRandomSample, you can test the There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. True, but is it worth redoing the test to break it up into those two separate cases? |
||
myRand := rand.New(rand.NewSource(1337)) | ||
var buf bytes.Buffer | ||
|
||
mylogger := func(msg string, args ...interface{}) { | ||
buf.WriteString(fmt.Sprintf(fmt.Sprintln(msg), args...)) | ||
} | ||
|
||
logRandomSampleImpl("This is test line 1", mylogger, 0.5, myRand.Float32) | ||
logRandomSampleImpl("This is test line 2", mylogger, 0.5, myRand.Float32) | ||
logRandomSampleImpl("This is test line 3", mylogger, 0.5, myRand.Float32) | ||
logRandomSampleImpl("This is test line 4", mylogger, 0.5, myRand.Float32) | ||
logRandomSampleImpl("This is test line 5", mylogger, 0.5, myRand.Float32) | ||
|
||
assert.EqualValues(t, expected, buf.String()) | ||
} |
Original file line number | Diff line number | Diff line change |
---|---|---|
|
@@ -10,13 +10,18 @@ import ( | |
"net/http" | ||
"time" | ||
|
||
"github.com/golang/glog" | ||
"github.com/prebid/prebid-server/config/util" | ||
|
||
"github.com/mxmCherry/openrtb" | ||
nativeRequests "github.com/mxmCherry/openrtb/native/request" | ||
nativeResponse "github.com/mxmCherry/openrtb/native/response" | ||
"github.com/prebid/prebid-server/adapters" | ||
"github.com/prebid/prebid-server/config" | ||
"github.com/prebid/prebid-server/currencies" | ||
"github.com/prebid/prebid-server/errortypes" | ||
"github.com/prebid/prebid-server/openrtb_ext" | ||
"github.com/prebid/prebid-server/pbsmetrics" | ||
"golang.org/x/net/context/ctxhttp" | ||
) | ||
|
||
|
@@ -82,16 +87,20 @@ type pbsOrtbSeatBid struct { | |
// | ||
// The name refers to the "Adapter" architecture pattern, and should not be confused with a Prebid "Adapter" | ||
// (which is being phased out and replaced by Bidder for OpenRTB auctions) | ||
func adaptBidder(bidder adapters.Bidder, client *http.Client) adaptedBidder { | ||
func adaptBidder(bidder adapters.Bidder, client *http.Client, cfg *config.Configuration, me pbsmetrics.MetricsEngine) adaptedBidder { | ||
return &bidderAdapter{ | ||
Bidder: bidder, | ||
Client: client, | ||
Bidder: bidder, | ||
Client: client, | ||
DebugCfg: cfg.Debug, | ||
me: me, | ||
} | ||
} | ||
|
||
type bidderAdapter struct { | ||
Bidder adapters.Bidder | ||
Client *http.Client | ||
Bidder adapters.Bidder | ||
Client *http.Client | ||
DebugCfg config.Debug | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Consider renaming to DebugConfig for ease of reading. |
||
me pbsmetrics.MetricsEngine | ||
} | ||
|
||
func (bidder *bidderAdapter) requestBid(ctx context.Context, request *openrtb.BidRequest, name openrtb_ext.BidderName, bidAdjustment float64, conversions currencies.Conversions, reqInfo *adapters.ExtraRequestInfo) (*pbsOrtbSeatBid, []error) { | ||
|
@@ -365,8 +374,21 @@ func (bidder *bidderAdapter) doTimeoutNotification(timeoutBidder adapters.Timeou | |
httpReq, err := http.NewRequest(toReq.Method, toReq.Uri, bytes.NewBuffer(toReq.Body)) | ||
if err == nil { | ||
httpReq.Header = req.Headers | ||
ctxhttp.Do(ctx, bidder.Client, httpReq) | ||
// No validation yet on sending notifications | ||
httpResp, err := ctxhttp.Do(ctx, bidder.Client, httpReq) | ||
success := (err == nil && httpResp.StatusCode >= 200 && httpResp.StatusCode < 300) | ||
bidder.me.RecordTimeoutNotice(success) | ||
if bidder.DebugCfg.TimeoutNotification.Log && !(bidder.DebugCfg.TimeoutNotification.FailOnly && success) { | ||
var msg string | ||
if err == nil { | ||
msg = fmt.Sprintf("TimeoutNotification: status:(%d) body:%s", httpResp.StatusCode, string(toReq.Body)) | ||
} else { | ||
msg = fmt.Sprintf("TimeoutNotification: error:(%s) body:%s", err.Error(), string(toReq.Body)) | ||
} | ||
// If logging is turned on, and logging is not disallowed via FailOnly | ||
util.LogRandomSample(msg, glog.Warningf, bidder.DebugCfg.TimeoutNotification.Sampling) | ||
} | ||
} else { | ||
bidder.me.RecordTimeoutNotice(false) | ||
} | ||
} | ||
|
||
|
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Should this function run inside
func (cfg *Configuration) validate() configErrors
? I can't find the place where it gets called.