Merge pull request #99079 from tkashem/throttle-message

add more context to client-go request throttling message

Kubernetes-commit: 83e140125c96bf9dbde46f4c13ebccb3909951cc

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