fix(auth): keep failure bookkeeping when cooling is disabled

sdk/cliproxy/auth/conductor_cooldown.go

@@ -714,6 +714,14 @@ func (m *Manager) MarkResult(ctx context.Context, result Result) {
 	setModelQuota := false
 	var authSnapshot *Auth
 	cooldownStateChanged := false
+	var (
+		logFailure        bool
+		logStatusCode     int
+		logClassification string
+		logCooldownStr    string
+		logBackoffLevel   int
+		logDisableCooling bool
+	)
 
 	m.mu.Lock()
 	if auth, ok := m.auths[result.AuthID]; ok && auth != nil {
@@ -749,6 +757,17 @@ func (m *Manager) MarkResult(ctx context.Context, result Result) {
 				clearAuthStateOnSuccess(auth, now)
 			}
 		} else {
+			logFailure = true
+			logStatusCode = statusCodeFromResult(result.Error)
+			logClassification = classifyFailureResult(result.Error, logStatusCode)
+			if result.CredentialScope && logClassification == "quota" {
+				logClassification = "credential_quota"
+			}
+			logDisableCooling = m.cooldownDisabledForAuth(auth)
+			if result.Error != nil && result.Error.Code == ErrorCodeForceCooldown {
+				logDisableCooling = false
+			}
+
 			if modelKey != "" {
 				if !shouldSkipCredentialCooldown(result.Error) {
 					disableCooling := m.cooldownDisabledForAuth(auth)
@@ -870,6 +889,8 @@ func (m *Manager) MarkResult(ctx context.Context, result Result) {
 								if state.Quota.Exceeded && state.Quota.NextRecoverAt.After(next) {
 									next = state.Quota.NextRecoverAt
 								}
+							} else {
+								_, backoffLevel = nextQuotaCooldown(state.Quota.BackoffLevel, false)
 							}
 							state.NextRetryAfter = next
 							state.Quota = QuotaState{
@@ -932,12 +953,30 @@ func (m *Manager) MarkResult(ctx context.Context, result Result) {
 					auth.UpdatedAt = now
 					updateAggregatedAvailability(auth, now)
 				}
+				if state := auth.ModelStates[modelKey]; state != nil {
+					logBackoffLevel = state.Quota.BackoffLevel
+					if !state.NextRetryAfter.IsZero() && state.NextRetryAfter.After(now) {
+						logCooldownStr = state.NextRetryAfter.Sub(now).Round(time.Second).String()
+					} else if !state.Quota.NextRecoverAt.IsZero() && state.Quota.NextRecoverAt.After(now) {
+						logCooldownStr = state.Quota.NextRecoverAt.Sub(now).Round(time.Second).String()
+					} else {
+						logCooldownStr = "skipped"
+					}
+				}
 			} else {
 				disableCooling := m.cooldownDisabledForAuth(auth)
 				if result.Error != nil && result.Error.Code == ErrorCodeForceCooldown {
 					disableCooling = false
 				}
 				applyAuthFailureState(auth, result.Error, result.RetryAfter, now, disableCooling)
+				logBackoffLevel = auth.Quota.BackoffLevel
+				if !auth.NextRetryAfter.IsZero() && auth.NextRetryAfter.After(now) {
+					logCooldownStr = auth.NextRetryAfter.Sub(now).Round(time.Second).String()
+				} else if !auth.Quota.NextRecoverAt.IsZero() && auth.Quota.NextRecoverAt.After(now) {
+					logCooldownStr = auth.Quota.NextRecoverAt.Sub(now).Round(time.Second).String()
+				} else {
+					logCooldownStr = "skipped"
+				}
 			}
 		}
 
@@ -949,6 +988,10 @@ func (m *Manager) MarkResult(ctx context.Context, result Result) {
 		}
 	}
 	m.mu.Unlock()
+	if logFailure {
+		entry := logEntryWithRequestID(ctx)
+		entry.Warnf("auth-cooldown: attempt failed | auth=%s status=%d class=%s cooldown=%s backoff=%d disable_cooling=%t", result.AuthID, logStatusCode, logClassification, logCooldownStr, logBackoffLevel, logDisableCooling)
+	}
 	if m.scheduler != nil && authSnapshot != nil {
 		m.scheduler.upsertAuth(authSnapshot)
 	}
@@ -1218,14 +1261,14 @@ func updateAggregatedAvailability(auth *Auth, now time.Time) {
 		if !stateUnavailable {
 			allUnavailable = false
 		}
+		if state.Quota.BackoffLevel > maxBackoffLevel {
+			maxBackoffLevel = state.Quota.BackoffLevel
+		}
 		if state.Quota.Exceeded {
 			quotaExceeded = true
 			if quotaRecover.IsZero() || (!state.Quota.NextRecoverAt.IsZero() && state.Quota.NextRecoverAt.Before(quotaRecover)) {
 				quotaRecover = state.Quota.NextRecoverAt
 			}
-			if state.Quota.BackoffLevel > maxBackoffLevel {
-				maxBackoffLevel = state.Quota.BackoffLevel
-			}
 		}
 	}
 	if !hasState {
@@ -1252,7 +1295,7 @@ func updateAggregatedAvailability(auth *Auth, now time.Time) {
 		auth.Quota.Exceeded = false
 		auth.Quota.Reason = ""
 		auth.Quota.NextRecoverAt = time.Time{}
-		auth.Quota.BackoffLevel = 0
+		auth.Quota.BackoffLevel = maxBackoffLevel
 	}
 }
 
@@ -1643,17 +1686,16 @@ func isCloudflareChallengeResultError(err *Error) bool {
 
 func nextCloudflareCooldown(backoffLevel int, disableCooling bool, now time.Time) (time.Time, int) {
 	var next time.Time
+	cooldown, nextLevel := nextQuotaCooldown(backoffLevel, false)
+	if cooldown < 10*time.Second {
+		cooldown = 10 * time.Second
+	}
 	if !disableCooling {
-		cooldown, nextLevel := nextQuotaCooldown(backoffLevel, disableCooling)
-		if cooldown < 10*time.Second {
-			cooldown = 10 * time.Second
-		}
 		if cooldown > 0 {
 			next = now.Add(cooldown)
 		}
-		backoffLevel = nextLevel
 	}
-	return next, backoffLevel
+	return next, nextLevel
 }
 
 func isRequestScopedNotFoundResultError(err *Error) bool {
@@ -2002,17 +2044,21 @@ func applyAuthFailureState(auth *Auth, resultErr *Error, retryAfter *time.Durati
 		auth.Quota.Exceeded = true
 		auth.Quota.Reason = "quota"
 		var next time.Time
+		backoffLevel := auth.Quota.BackoffLevel
 		if !disableCooling {
 			if retryAfter != nil {
 				next = now.Add(*retryAfter)
 			} else {
-				next, auth.Quota.BackoffLevel = quotaCooldownAfterFailure(auth.Quota, now)
+				next, backoffLevel = quotaCooldownAfterFailure(auth.Quota, now)
 			}
 			if auth.Quota.Exceeded && auth.Quota.NextRecoverAt.After(next) {
 				next = auth.Quota.NextRecoverAt
 			}
+		} else {
+			_, backoffLevel = nextQuotaCooldown(auth.Quota.BackoffLevel, false)
 		}
 		auth.Quota.NextRecoverAt = next
+		auth.Quota.BackoffLevel = backoffLevel
 		auth.NextRetryAfter = next
 	case 408, 500, 502, 503, 504:
 		auth.StatusMessage = "transient upstream error"
@@ -2031,6 +2077,39 @@ func applyAuthFailureState(auth *Auth, resultErr *Error, retryAfter *time.Durati
 	}
 }
 
+func classifyFailureResult(err *Error, statusCode int) string {
+	switch {
+	case isModelSupportResultError(err):
+		return "model_not_supported"
+	case isCloudflareChallengeResultError(err):
+		return "cloudflare_challenge"
+	case isInvalidGrantResultError(err):
+		return "invalid_grant"
+	case isInvalidAPIKeyResultError(err):
+		return "invalid_api_key"
+	case isRequestScopedResultError(err):
+		return "request_scoped"
+	case isConnectionLifecycleResultError(err):
+		return "connection_lifecycle"
+	case statusCode == http.StatusUnauthorized:
+		return "unauthorized"
+	case statusCode == http.StatusPaymentRequired || statusCode == http.StatusForbidden:
+		return "payment_required"
+	case statusCode == http.StatusNotFound:
+		return "not_found"
+	case statusCode == http.StatusTooManyRequests:
+		return "quota"
+	case statusCode == http.StatusRequestTimeout ||
+		statusCode == http.StatusInternalServerError ||
+		statusCode == http.StatusBadGateway ||
+		statusCode == http.StatusServiceUnavailable ||
+		statusCode == http.StatusGatewayTimeout:
+		return "transient_upstream_error"
+	default:
+		return "request_failed"
+	}
+}
+
 // quotaCooldownAfterFailure returns the recovery deadline and backoff level for
 // a quota failure observed at now. Failures that land while a previous quota
 // window is still open reuse that window instead of escalating, so a burst of
@@ -2053,15 +2132,17 @@ func nextQuotaCooldown(prevLevel int, disableCooling bool) (time.Duration, int)
 	if prevLevel < 0 {
 		prevLevel = 0
 	}
-	if disableCooling {
-		return 0, prevLevel
-	}
 	cooldown := quotaBackoffBase * time.Duration(1<<prevLevel)
 	if cooldown < quotaBackoffBase {
 		cooldown = quotaBackoffBase
 	}
+	nextLevel := prevLevel + 1
 	if cooldown >= quotaBackoffMax {
-		return quotaBackoffMax, prevLevel
+		cooldown = quotaBackoffMax
+		nextLevel = prevLevel
+	}
+	if disableCooling {
+		return 0, nextLevel
 	}
-	return cooldown, prevLevel + 1
+	return cooldown, nextLevel
 }