-
Notifications
You must be signed in to change notification settings - Fork 207
Commit
This commit does not belong to any branch on this repository, and may belong to a fork outside of the repository.
Added a custom retryer implementation to log any throttling events ha…
…ndled by the SDK. (#243)
- Loading branch information
Showing
4 changed files
with
246 additions
and
1 deletion.
There are no files selected for viewing
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,93 @@ | ||
| package retryer | ||
|
|
||
| import ( | ||
| "time" | ||
|
|
||
| "github.com/aws/aws-sdk-go/aws/client" | ||
| "github.com/aws/aws-sdk-go/aws/request" | ||
| "github.com/influxdata/telegraf" | ||
| ) | ||
|
|
||
| var ( | ||
| throttleReportTimeout = 1 * time.Minute | ||
| throttleReportCheckPeriod = 5 * time.Second | ||
| ) | ||
|
|
||
| type LogThrottleRetryer struct { | ||
| Log telegraf.Logger | ||
|
|
||
| throttleChan chan error | ||
| done chan struct{} | ||
|
|
||
| client.DefaultRetryer | ||
| } | ||
|
|
||
| func NewLogThrottleRetryer(logger telegraf.Logger) *LogThrottleRetryer { | ||
| r := &LogThrottleRetryer{ | ||
| Log: logger, | ||
| throttleChan: make(chan error, 1), | ||
| done: make(chan struct{}), | ||
| DefaultRetryer: client.DefaultRetryer{NumMaxRetries: client.DefaultRetryerMaxNumRetries}, | ||
| } | ||
|
|
||
| go r.watchThrottleEvents() | ||
| return r | ||
| } | ||
|
|
||
| func (r *LogThrottleRetryer) ShouldRetry(req *request.Request) bool { | ||
| if req.IsErrorThrottle() { | ||
| r.throttleChan <- req.Error | ||
| } | ||
|
|
||
| // Fallback to SDK's built in retry rules | ||
| return r.DefaultRetryer.ShouldRetry(req) | ||
| } | ||
|
|
||
| func (r *LogThrottleRetryer) Stop() { | ||
| if r != nil { | ||
| close(r.done) | ||
| } | ||
| } | ||
|
|
||
| func (r *LogThrottleRetryer) watchThrottleEvents() { | ||
| ticker := time.NewTicker(throttleReportCheckPeriod) | ||
| defer ticker.Stop() | ||
|
|
||
| var start time.Time | ||
| var err error | ||
| cnt := 0 | ||
| for { | ||
| select { | ||
| case err = <-r.throttleChan: | ||
| // Log first throttle if there has not been any recent throttling events | ||
| if cnt == 0 { | ||
| if time.Since(start) > 2*throttleReportTimeout { | ||
| r.Log.Infof("aws api call throttling detected: %v", err) | ||
| } else { | ||
| r.Log.Debugf("aws api call throttling detected: %v", err) | ||
| } | ||
| start = time.Now() | ||
| } else { | ||
| r.Log.Debugf("aws api call throttling detected: %v", err) | ||
| } | ||
| cnt++ | ||
| case <-ticker.C: | ||
| if cnt == 0 { | ||
| continue | ||
| } | ||
| d := time.Since(start) | ||
| if d > throttleReportTimeout { | ||
| if cnt > 1 { | ||
| r.Log.Infof("aws api call has been throttled for %v times in the past %v, last throttle error message: %v", cnt, d, err) | ||
| } | ||
| cnt = 0 | ||
| } | ||
| case <-r.done: | ||
| if cnt > 0 { | ||
| r.Log.Infof("aws api call has been throttled for %v times in the past %v, last throttle error message: %v", cnt, time.Since(start), err) | ||
| } | ||
| r.Log.Debugf("LogThrottleRetryer watch throttle events goroutine exiting") | ||
| return | ||
| } | ||
| } | ||
| } |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,139 @@ | ||
| package retryer | ||
|
|
||
| import ( | ||
| "fmt" | ||
| "strings" | ||
| "testing" | ||
| "time" | ||
|
|
||
| "github.com/aws/aws-sdk-go/aws/awserr" | ||
| "github.com/aws/aws-sdk-go/aws/request" | ||
| ) | ||
|
|
||
| type testLogger struct { | ||
| debugs, infos, warns, errors []string | ||
| } | ||
|
|
||
| func (l *testLogger) Errorf(format string, args ...interface{}) { | ||
| line := fmt.Sprintf(format, args...) | ||
| l.errors = append(l.errors, line) | ||
| } | ||
|
|
||
| func (l *testLogger) Error(args ...interface{}) { | ||
| line := fmt.Sprint(args...) | ||
| l.errors = append(l.errors, line) | ||
| } | ||
|
|
||
| func (l *testLogger) Debugf(format string, args ...interface{}) { | ||
| line := fmt.Sprintf(format, args...) | ||
| l.debugs = append(l.debugs, line) | ||
| } | ||
|
|
||
| func (l *testLogger) Debug(args ...interface{}) { | ||
| line := fmt.Sprint(args...) | ||
| l.debugs = append(l.debugs, line) | ||
| } | ||
|
|
||
| func (l *testLogger) Warnf(format string, args ...interface{}) { | ||
| line := fmt.Sprintf(format, args...) | ||
| l.warns = append(l.warns, line) | ||
| } | ||
|
|
||
| func (l *testLogger) Warn(args ...interface{}) { | ||
| line := fmt.Sprint(args...) | ||
| l.warns = append(l.warns, line) | ||
| } | ||
|
|
||
| func (l *testLogger) Infof(format string, args ...interface{}) { | ||
| line := fmt.Sprintf(format, args...) | ||
| l.infos = append(l.infos, line) | ||
| } | ||
|
|
||
| func (l *testLogger) Info(args ...interface{}) { | ||
| line := fmt.Sprint(args...) | ||
| l.infos = append(l.infos, line) | ||
| } | ||
|
|
||
| func TestLogThrottleRetryerLogging(t *testing.T) { | ||
| const throttleDetectedLine = "aws api call throttling detected: RequestLimitExceeded: Test AWS Error" | ||
| const watchGoroutineExitLine = "LogThrottleRetryer watch throttle events goroutine exiting" | ||
| const throttleSummaryLinePrefix = "aws api call has been throttled for" | ||
| const throttleBatchSize = 100 | ||
| const totalThrottleCnt = throttleBatchSize * 2 // Test total 2 batches | ||
| const expectedDebugCnt = totalThrottleCnt - 2 // 2 of them are being log at info level | ||
|
|
||
| setup() | ||
| defer tearDown() | ||
|
|
||
| l := &testLogger{} | ||
| r := NewLogThrottleRetryer(l) | ||
|
|
||
| req := &request.Request{ | ||
| Error: awserr.New("RequestLimitExceeded", "Test AWS Error", nil), | ||
| } | ||
|
|
||
| // Generate 200 throttles with a time gap between | ||
| for i := 0; i < throttleBatchSize; i++ { | ||
| r.ShouldRetry(req) | ||
| time.Sleep(10 * time.Millisecond) | ||
| } | ||
|
|
||
| time.Sleep(1500 * time.Millisecond) | ||
|
|
||
| for i := 0; i < throttleBatchSize; i++ { | ||
| r.ShouldRetry(req) | ||
| time.Sleep(10 * time.Millisecond) | ||
| } | ||
|
|
||
| r.Stop() | ||
| time.Sleep(200 * time.Millisecond) // Wait a bit to collect all logs | ||
|
|
||
| // Check the debug level log messages | ||
| debugCnt := 0 | ||
| for _, d := range l.debugs { | ||
| if d == throttleDetectedLine { | ||
| debugCnt++ | ||
| } else if d != watchGoroutineExitLine { | ||
| t.Errorf("unexpected debug log found: %v", d) | ||
| } | ||
| } | ||
| if debugCnt != expectedDebugCnt { | ||
| t.Errorf("wrong number of debug logs found, expected") | ||
| } | ||
|
|
||
| // Check the info level log messages | ||
| detectCnt := 0 | ||
| throttleCnt := 0 | ||
| for i, info := range l.infos { | ||
| if info == throttleDetectedLine { | ||
| if i > 0 { | ||
| if throttleCnt != throttleBatchSize { | ||
| t.Errorf("wrong number of throttle count reported, expecting %v, got %v", throttleBatchSize, throttleCnt) | ||
| } | ||
| } | ||
| detectCnt++ | ||
| throttleCnt = 0 | ||
| } else if strings.HasPrefix(info, throttleSummaryLinePrefix) { | ||
| n := 0 | ||
| fmt.Sscanf(info, throttleSummaryLinePrefix+" %d", &n) | ||
| throttleCnt += n | ||
| } | ||
| } | ||
|
|
||
| if detectCnt != 2 { | ||
| t.Errorf("wrong number of throttle detected info log found, expecting 2, got %v", detectCnt) | ||
| } | ||
| if throttleCnt != throttleBatchSize { | ||
| t.Errorf("wrong number of throttle count reported, expecting %v, got %v", throttleBatchSize, throttleCnt) | ||
| } | ||
| } | ||
|
|
||
| func setup() { | ||
| throttleReportTimeout = 400 * time.Millisecond | ||
| throttleReportCheckPeriod = 50 * time.Millisecond | ||
| } | ||
|
|
||
| func tearDown() { | ||
| throttleReportTimeout = 1 * time.Minute | ||
| throttleReportCheckPeriod = 5 * time.Second | ||
| } |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters