diff --git a/rest/request.go b/rest/request.go index 1ccc0daf..f39b264f 100644 --- a/rest/request.go +++ b/rest/request.go @@ -577,7 +577,7 @@ func (r Request) finalURLTemplate() url.URL { return *url } -func (r *Request) tryThrottle(ctx context.Context) error { +func (r *Request) tryThrottleWithInfo(ctx context.Context, retryInfo string) error { if r.rateLimiter == nil { return nil } @@ -587,19 +587,32 @@ func (r *Request) tryThrottle(ctx context.Context) error { err := r.rateLimiter.Wait(ctx) latency := time.Since(now) + + var message string + switch { + case len(retryInfo) > 0: + message = fmt.Sprintf("Waited for %v, %s - request: %s:%s", latency, retryInfo, r.verb, r.URL().String()) + default: + message = fmt.Sprintf("Waited for %v due to client-side throttling, not priority and fairness, request: %s:%s", latency, r.verb, r.URL().String()) + } + if latency > longThrottleLatency { - klog.V(3).Infof("Throttling request took %v, request: %s:%s", latency, r.verb, r.URL().String()) + klog.V(3).Info(message) } if latency > extraLongThrottleLatency { // If the rate limiter latency is very high, the log message should be printed at a higher log level, // but we use a throttled logger to prevent spamming. - globalThrottledLogger.Infof("Throttling request took %v, request: %s:%s", latency, r.verb, r.URL().String()) + globalThrottledLogger.Infof(message) } metrics.RateLimiterLatency.Observe(r.verb, r.finalURLTemplate(), latency) return err } +func (r *Request) tryThrottle(ctx context.Context) error { + return r.tryThrottleWithInfo(ctx, "") +} + type throttleSettings struct { logLevel klog.Level minLogInterval time.Duration @@ -869,6 +882,7 @@ func (r *Request) request(ctx context.Context, fn func(*http.Request, *http.Resp // Right now we make about ten retry attempts if we get a Retry-After response. retries := 0 + var retryInfo string for { url := r.URL().String() @@ -884,9 +898,10 @@ func (r *Request) request(ctx context.Context, fn func(*http.Request, *http.Resp // We are retrying the request that we already send to apiserver // at least once before. // This request should also be throttled with the client-internal rate limiter. - if err := r.tryThrottle(ctx); err != nil { + if err := r.tryThrottleWithInfo(ctx, retryInfo); err != nil { return err } + retryInfo = "" } resp, err := client.Do(req) updateURLMetrics(r, resp, err) @@ -931,6 +946,7 @@ func (r *Request) request(ctx context.Context, fn func(*http.Request, *http.Resp retries++ if seconds, wait := checkWait(resp); wait && retries <= r.maxRetries { + retryInfo = getRetryReason(retries, seconds, resp, err) if seeker, ok := r.body.(io.Seeker); ok && r.body != nil { _, err := seeker.Seek(0, 0) if err != nil { @@ -1204,6 +1220,26 @@ func retryAfterSeconds(resp *http.Response) (int, bool) { return 0, false } +func getRetryReason(retries, seconds int, resp *http.Response, err error) string { + // priority and fairness sets the UID of the FlowSchema associated with a request + // in the following response Header. + const responseHeaderMatchedFlowSchemaUID = "X-Kubernetes-PF-FlowSchema-UID" + + message := fmt.Sprintf("retries: %d, retry-after: %ds", retries, seconds) + + switch { + case resp.StatusCode == http.StatusTooManyRequests: + // it is server-side throttling from priority and fairness + flowSchemaUID := resp.Header.Get(responseHeaderMatchedFlowSchemaUID) + return fmt.Sprintf("%s - retry-reason: due to server-side throttling, FlowSchema UID: %q", message, flowSchemaUID) + case err != nil: + // it's a retriable error + return fmt.Sprintf("%s - retry-reason: due to retriable error, error: %v", message, err) + default: + return fmt.Sprintf("%s - retry-reason: %d", message, resp.StatusCode) + } +} + // Result contains the result of calling Request.Do(). type Result struct { body []byte