diff --git a/sdk/cliproxy/auth/conductor_cooldown.go b/sdk/cliproxy/auth/conductor_cooldown.go index 931aef868..8e83616b2 100644 --- a/sdk/cliproxy/auth/conductor_cooldown.go +++ b/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<= quotaBackoffMax { - return quotaBackoffMax, prevLevel + cooldown = quotaBackoffMax + nextLevel = prevLevel + } + if disableCooling { + return 0, nextLevel } - return cooldown, prevLevel + 1 + return cooldown, nextLevel } diff --git a/sdk/cliproxy/auth/cooldown_backoff_test.go b/sdk/cliproxy/auth/cooldown_backoff_test.go index 73a7bdcf3..cf67afb92 100644 --- a/sdk/cliproxy/auth/cooldown_backoff_test.go +++ b/sdk/cliproxy/auth/cooldown_backoff_test.go @@ -3,11 +3,13 @@ package auth import ( "context" "net/http" + "strings" "testing" "time" "github.com/router-for-me/CLIProxyAPI/v7/internal/registry" cliproxyexecutor "github.com/router-for-me/CLIProxyAPI/v7/sdk/cliproxy/executor" + log "github.com/sirupsen/logrus" ) func withQuotaCooldownEnabled(t *testing.T) { @@ -308,3 +310,198 @@ func TestJitteredCooldownWaitBounds(t *testing.T) { t.Fatalf("expected sub-4ns wait to stay unchanged, got %v", got) } } + +func TestDisableCoolingRecordsBackoffAndTimestampWhileStayingUsable(t *testing.T) { + manager := NewManager(nil, nil, nil) + auth := &Auth{ + ID: "auth-disable-cooling-records", + Provider: "codex", + Metadata: map[string]any{ + "type": "codex", + "disable_cooling": true, + }, + } + if _, errRegister := manager.Register(WithSkipPersist(context.Background()), auth); errRegister != nil { + t.Fatalf("Register returned error: %v", errRegister) + } + + modelRegistry := registry.GetGlobalRegistry() + modelRegistry.RegisterClient(auth.ID, "codex", []*registry.ModelInfo{{ID: "gpt-5"}}) + t.Cleanup(func() { modelRegistry.UnregisterClient(auth.ID) }) + + beforeFail := time.Now().Add(-time.Second) + manager.MarkResult(context.Background(), quotaResult(auth.ID, "gpt-5")) + afterFail := time.Now().Add(time.Second) + + first, ok := manager.GetByID(auth.ID) + if !ok || first == nil || first.ModelStates["gpt-5"] == nil { + t.Fatalf("expected model state after first failure") + } + firstState := first.ModelStates["gpt-5"] + if firstState.Unavailable { + t.Fatalf("expected Unavailable=false when disable_cooling=true, got true") + } + if firstState.Quota.Exceeded { + t.Fatalf("expected Quota.Exceeded=false when disable_cooling=true, got true") + } + if !firstState.NextRetryAfter.IsZero() { + t.Fatalf("expected NextRetryAfter to be zero when disable_cooling=true, got %v", firstState.NextRetryAfter) + } + if !firstState.Quota.NextRecoverAt.IsZero() { + t.Fatalf("expected NextRecoverAt to be zero when disable_cooling=true, got %v", firstState.Quota.NextRecoverAt) + } + if firstState.Quota.BackoffLevel != 1 { + t.Fatalf("expected BackoffLevel=1 after first failure, got %d", firstState.Quota.BackoffLevel) + } + if first.Quota.BackoffLevel != 1 { + t.Fatalf("expected auth-level BackoffLevel=1 after first failure, got %d", first.Quota.BackoffLevel) + } + if firstState.UpdatedAt.Before(beforeFail) || firstState.UpdatedAt.After(afterFail) { + t.Fatalf("expected UpdatedAt timestamp to be set near now, got %v", firstState.UpdatedAt) + } + + blocked, _, _ := isAuthBlockedForModel(first, "gpt-5", time.Now()) + if blocked { + t.Fatalf("expected credential to stay usable (not blocked) when disable_cooling=true") + } + + // Second failure advances the backoff level further + manager.MarkResult(context.Background(), quotaResult(auth.ID, "gpt-5")) + + second, ok := manager.GetByID(auth.ID) + if !ok || second == nil || second.ModelStates["gpt-5"] == nil { + t.Fatalf("expected model state after second failure") + } + secondState := second.ModelStates["gpt-5"] + if secondState.Unavailable { + t.Fatalf("expected Unavailable=false after second failure, got true") + } + if secondState.Quota.Exceeded { + t.Fatalf("expected Quota.Exceeded=false after second failure, got true") + } + if secondState.Quota.BackoffLevel != 2 { + t.Fatalf("expected BackoffLevel=2 after second failure, got %d", secondState.Quota.BackoffLevel) + } + if second.Quota.BackoffLevel != 2 { + t.Fatalf("expected auth-level BackoffLevel=2 after second failure, got %d", second.Quota.BackoffLevel) + } + + blockedSecond, _, _ := isAuthBlockedForModel(second, "gpt-5", time.Now()) + if blockedSecond { + t.Fatalf("expected credential to stay usable after second failure") + } +} + +func TestDisableCoolingDisabledKeepsStandardCooldownBehavior(t *testing.T) { + withQuotaCooldownEnabled(t) + + manager := NewManager(nil, nil, nil) + auth := &Auth{ + ID: "auth-normal-cooling", + Provider: "codex", + Metadata: map[string]any{ + "type": "codex", + "disable_cooling": false, + }, + } + if _, errRegister := manager.Register(WithSkipPersist(context.Background()), auth); errRegister != nil { + t.Fatalf("Register returned error: %v", errRegister) + } + + modelRegistry := registry.GetGlobalRegistry() + modelRegistry.RegisterClient(auth.ID, "codex", []*registry.ModelInfo{{ID: "gpt-5"}}) + t.Cleanup(func() { modelRegistry.UnregisterClient(auth.ID) }) + + manager.MarkResult(context.Background(), quotaResult(auth.ID, "gpt-5")) + + updated, ok := manager.GetByID(auth.ID) + if !ok || updated == nil || updated.ModelStates["gpt-5"] == nil { + t.Fatalf("expected model state after failure") + } + state := updated.ModelStates["gpt-5"] + if !state.Unavailable { + t.Fatalf("expected Unavailable=true when disable_cooling=false") + } + if !state.Quota.Exceeded { + t.Fatalf("expected Quota.Exceeded=true when disable_cooling=false") + } + if state.NextRetryAfter.IsZero() || !state.NextRetryAfter.After(time.Now()) { + t.Fatalf("expected NextRetryAfter in the future, got %v", state.NextRetryAfter) + } + if state.Quota.NextRecoverAt.IsZero() || !state.Quota.NextRecoverAt.After(time.Now()) { + t.Fatalf("expected NextRecoverAt in the future, got %v", state.Quota.NextRecoverAt) + } + if state.Quota.BackoffLevel != 1 { + t.Fatalf("expected BackoffLevel=1, got %d", state.Quota.BackoffLevel) + } + + blocked, _, _ := isAuthBlockedForModel(updated, "gpt-5", time.Now()) + if !blocked { + t.Fatalf("expected credential to be blocked when cooling is enabled") + } +} + +type testLogCaptureHook struct { + messages []string +} + +func (h *testLogCaptureHook) Levels() []log.Level { + return log.AllLevels +} + +func (h *testLogCaptureHook) Fire(entry *log.Entry) error { + h.messages = append(h.messages, entry.Message) + return nil +} + +func TestMarkResultPerAttemptFailureLogging(t *testing.T) { + hook := &testLogCaptureHook{} + logger := log.StandardLogger() + savedHooks := make(log.LevelHooks) + for lvl, hs := range logger.Hooks { + savedHooks[lvl] = append([]log.Hook(nil), hs...) + } + logger.AddHook(hook) + t.Cleanup(func() { + logger.ReplaceHooks(savedHooks) + }) + + manager := NewManager(nil, nil, nil) + auth := &Auth{ + ID: "auth-log-test", + Provider: "codex", + Metadata: map[string]any{ + "type": "codex", + "disable_cooling": true, + }, + } + if _, errRegister := manager.Register(WithSkipPersist(context.Background()), auth); errRegister != nil { + t.Fatalf("Register returned error: %v", errRegister) + } + + modelRegistry := registry.GetGlobalRegistry() + modelRegistry.RegisterClient(auth.ID, "codex", []*registry.ModelInfo{{ID: "gpt-5"}}) + t.Cleanup(func() { modelRegistry.UnregisterClient(auth.ID) }) + + manager.MarkResult(context.Background(), quotaResult(auth.ID, "gpt-5")) + + found := false + var matchedMsg string + for _, msg := range hook.messages { + if strings.Contains(msg, "auth-cooldown: attempt failed") && strings.Contains(msg, "auth=auth-log-test") { + found = true + matchedMsg = msg + break + } + } + if !found { + t.Fatalf("expected log line 'auth-cooldown: attempt failed' for auth-log-test, got messages: %v", hook.messages) + } + if !strings.Contains(matchedMsg, "status=429") || + !strings.Contains(matchedMsg, "class=quota") || + !strings.Contains(matchedMsg, "cooldown=skipped") || + !strings.Contains(matchedMsg, "backoff=1") || + !strings.Contains(matchedMsg, "disable_cooling=true") { + t.Fatalf("unexpected log message format: %s", matchedMsg) + } +}