oadmin/sub2api
1
0
Fork 0
Code Issues Pull Requests 1 Actions 2 Packages Projects Releases Wiki Activity

fix(sora): 优化 challenge 重试与调试日志

Browse Source
This commit is contained in:
yangjianbo
2026-02-19 21:38:04 +08:00
parent 46d9aee6dd
commit b341810e60
4 changed files with 303 additions and 22 deletions
Download Patch File Download Diff File Expand all files Collapse all files

99
backend/internal/service/sora_client.go
View File

@@ -234,6 +234,14 @@ type SoraDirectClient struct {
sidecarSessions map[string]soraSidecarSessionEntry
}
type soraRequestTraceContextKey struct{}
type soraRequestTrace struct {
ID string
ProxyKey string
UAHash string
}
// NewSoraDirectClient 创建 Sora 直连客户端
func NewSoraDirectClient(cfg *config.Config, httpUpstream HTTPUpstream, tokenProvider *OpenAITokenProvider) *SoraDirectClient {
baseURL := ""
@@ -377,6 +385,7 @@ func (c *SoraDirectClient) CreateImageTask(ctx context.Context, account *Account
}
userAgent := c.taskUserAgent()
proxyURL := c.resolveProxyURL(account)
ctx = c.withRequestTrace(ctx, account, proxyURL, userAgent)
operation := "simple_compose"
inpaintItems := []map[string]any{}
if strings.TrimSpace(req.MediaID) != "" {
@@ -430,6 +439,7 @@ func (c *SoraDirectClient) CreateVideoTask(ctx context.Context, account *Account
}
userAgent := c.taskUserAgent()
proxyURL := c.resolveProxyURL(account)
ctx = c.withRequestTrace(ctx, account, proxyURL, userAgent)
orientation := req.Orientation
if orientation == "" {
orientation = "landscape"
@@ -504,6 +514,7 @@ func (c *SoraDirectClient) CreateStoryboardTask(ctx context.Context, account *Ac
}
userAgent := c.taskUserAgent()
proxyURL := c.resolveProxyURL(account)
ctx = c.withRequestTrace(ctx, account, proxyURL, userAgent)
orientation := req.Orientation
if orientation == "" {
orientation = "landscape"
@@ -724,6 +735,7 @@ func (c *SoraDirectClient) FinalizeCharacter(ctx context.Context, account *Accou
}
userAgent := c.taskUserAgent()
proxyURL := c.resolveProxyURL(account)
ctx = c.withRequestTrace(ctx, account, proxyURL, userAgent)
payload := map[string]any{
"cameo_id": req.CameoID,
"username": req.Username,
@@ -808,6 +820,7 @@ func (c *SoraDirectClient) PostVideoForWatermarkFree(ctx context.Context, accoun
}
userAgent := c.taskUserAgent()
proxyURL := c.resolveProxyURL(account)
ctx = c.withRequestTrace(ctx, account, proxyURL, userAgent)
payload := map[string]any{
"attachments_to_create": []map[string]any{
{
@@ -1471,6 +1484,7 @@ func (c *SoraDirectClient) doRequestWithProxy(
if cooldownErr := c.checkCloudflareChallengeCooldown(account, proxyURL); cooldownErr != nil {
return nil, nil, cooldownErr
}
traceID, traceProxyKey, traceUAHash := c.requestTraceFields(ctx, proxyURL, headers.Get("User-Agent"))
timeout := 0
if c != nil && c.cfg != nil {
timeout = c.cfg.Sora.Client.TimeoutSeconds
@@ -1500,11 +1514,14 @@ func (c *SoraDirectClient) doRequestWithProxy(
attempts := maxRetries + 1
authRecovered := false
authRecoverExtraAttemptGranted := false
challengeRetried := false
sawCFChallenge := false
var lastErr error
for attempt := 1; attempt <= attempts; attempt++ {
if c.debugEnabled() {
c.debugLogf(
"request_start method=%s url=%s attempt=%d/%d timeout_s=%d body_bytes=%d proxy_bound=%t headers=%s",
"request_start trace_id=%s method=%s url=%s attempt=%d/%d timeout_s=%d body_bytes=%d proxy_bound=%t proxy_key=%s ua_hash=%s headers=%s",
traceID,
method,
sanitizeSoraLogURL(urlStr),
attempt,
@@ -1512,6 +1529,8 @@ func (c *SoraDirectClient) doRequestWithProxy(
timeout,
len(bodyBytes),
proxyURL != "",
traceProxyKey,
traceUAHash,
formatSoraHeaders(headers),
)
}
@@ -1532,7 +1551,8 @@ func (c *SoraDirectClient) doRequestWithProxy(
lastErr = err
if c.debugEnabled() {
c.debugLogf(
"request_transport_error method=%s url=%s attempt=%d/%d err=%s",
"request_transport_error trace_id=%s method=%s url=%s attempt=%d/%d err=%s",
traceID,
method,
sanitizeSoraLogURL(urlStr),
attempt,
@@ -1542,7 +1562,7 @@ func (c *SoraDirectClient) doRequestWithProxy(
}
if attempt < attempts && allowRetry {
if c.debugEnabled() {
c.debugLogf("request_retry_scheduled method=%s url=%s reason=transport_error next_attempt=%d/%d", method, sanitizeSoraLogURL(urlStr), attempt+1, attempts)
c.debugLogf("request_retry_scheduled trace_id=%s method=%s url=%s reason=transport_error next_attempt=%d/%d", traceID, method, sanitizeSoraLogURL(urlStr), attempt+1, attempts)
}
c.sleepRetry(attempt)
continue
@@ -1558,7 +1578,8 @@ func (c *SoraDirectClient) doRequestWithProxy(
if c.cfg != nil && c.cfg.Sora.Client.Debug {
c.debugLogf(
"response_received method=%s url=%s attempt=%d/%d status=%d cost=%s resp_bytes=%d resp_headers=%s",
"response_received trace_id=%s method=%s url=%s attempt=%d/%d status=%d cost=%s resp_bytes=%d resp_headers=%s",
traceID,
method,
sanitizeSoraLogURL(urlStr),
attempt,
@@ -1573,7 +1594,16 @@ func (c *SoraDirectClient) doRequestWithProxy(
if resp.StatusCode != http.StatusOK && resp.StatusCode != http.StatusCreated {
isCFChallenge := soraerror.IsCloudflareChallengeResponse(resp.StatusCode, resp.Header, respBody)
if isCFChallenge {
sawCFChallenge = true
c.recordCloudflareChallengeCooldown(account, proxyURL, resp.StatusCode, resp.Header, respBody)
if allowRetry && attempt < attempts && !challengeRetried {
challengeRetried = true
if c.debugEnabled() {
c.debugLogf("request_retry_scheduled trace_id=%s method=%s url=%s reason=cloudflare_challenge status=%d next_attempt=%d/%d", traceID, method, sanitizeSoraLogURL(urlStr), resp.StatusCode, attempt+1, attempts)
}
c.sleepRetry(attempt)
continue
}
}
if !isCFChallenge && !authRecovered && shouldAttemptSoraTokenRecover(resp.StatusCode, urlStr) && account != nil {
if recovered, recoverErr := c.recoverAccessToken(ctx, account, fmt.Sprintf("upstream_status_%d", resp.StatusCode)); recoverErr == nil && strings.TrimSpace(recovered) != "" {
@@ -1584,16 +1614,17 @@ func (c *SoraDirectClient) doRequestWithProxy(
authRecoverExtraAttemptGranted = true
}
if c.debugEnabled() {
c.debugLogf("request_retry_with_recovered_token method=%s url=%s status=%d", method, sanitizeSoraLogURL(urlStr), resp.StatusCode)
c.debugLogf("request_retry_with_recovered_token trace_id=%s method=%s url=%s status=%d", traceID, method, sanitizeSoraLogURL(urlStr), resp.StatusCode)
}
continue
} else if recoverErr != nil && c.debugEnabled() {
c.debugLogf("request_recover_token_failed method=%s url=%s status=%d err=%s", method, sanitizeSoraLogURL(urlStr), resp.StatusCode, logredact.RedactText(recoverErr.Error()))
c.debugLogf("request_recover_token_failed trace_id=%s method=%s url=%s status=%d err=%s", traceID, method, sanitizeSoraLogURL(urlStr), resp.StatusCode, logredact.RedactText(recoverErr.Error()))
}
}
if c.debugEnabled() {
c.debugLogf(
"response_non_success method=%s url=%s attempt=%d/%d status=%d body=%s",
"response_non_success trace_id=%s method=%s url=%s attempt=%d/%d status=%d body=%s",
traceID,
method,
sanitizeSoraLogURL(urlStr),
attempt,
@@ -1609,13 +1640,16 @@ func (c *SoraDirectClient) doRequestWithProxy(
}
if allowRetry && attempt < attempts && (resp.StatusCode == http.StatusTooManyRequests || resp.StatusCode >= 500) {
if c.debugEnabled() {
c.debugLogf("request_retry_scheduled method=%s url=%s reason=status_%d next_attempt=%d/%d", method, sanitizeSoraLogURL(urlStr), resp.StatusCode, attempt+1, attempts)
c.debugLogf("request_retry_scheduled trace_id=%s method=%s url=%s reason=status_%d next_attempt=%d/%d", traceID, method, sanitizeSoraLogURL(urlStr), resp.StatusCode, attempt+1, attempts)
}
c.sleepRetry(attempt)
continue
}
return nil, resp.Header, upstreamErr
}
if sawCFChallenge {
c.clearCloudflareChallengeCooldown(account, proxyURL)
}
return respBody, resp.Header, nil
}
if lastErr != nil {
@@ -1960,6 +1994,55 @@ func hexDecodeString(s string) ([]byte, error) {
return dst, err
}
func (c *SoraDirectClient) withRequestTrace(ctx context.Context, account *Account, proxyURL, userAgent string) context.Context {
if ctx == nil {
ctx = context.Background()
}
if existing, ok := ctx.Value(soraRequestTraceContextKey{}).(*soraRequestTrace); ok && existing != nil && existing.ID != "" {
return ctx
}
accountID := int64(0)
if account != nil {
accountID = account.ID
}
seed := fmt.Sprintf("%d|%s|%s|%d", accountID, normalizeSoraProxyKey(proxyURL), strings.TrimSpace(userAgent), time.Now().UnixNano())
trace := &soraRequestTrace{
ID: "sora-" + soraHashForLog(seed),
ProxyKey: normalizeSoraProxyKey(proxyURL),
UAHash: soraHashForLog(strings.TrimSpace(userAgent)),
}
return context.WithValue(ctx, soraRequestTraceContextKey{}, trace)
}
func (c *SoraDirectClient) requestTraceFields(ctx context.Context, proxyURL, userAgent string) (string, string, string) {
proxyKey := normalizeSoraProxyKey(proxyURL)
uaHash := soraHashForLog(strings.TrimSpace(userAgent))
traceID := ""
if ctx != nil {
if trace, ok := ctx.Value(soraRequestTraceContextKey{}).(*soraRequestTrace); ok && trace != nil {
if strings.TrimSpace(trace.ID) != "" {
traceID = strings.TrimSpace(trace.ID)
}
if strings.TrimSpace(trace.ProxyKey) != "" {
proxyKey = strings.TrimSpace(trace.ProxyKey)
}
if strings.TrimSpace(trace.UAHash) != "" {
uaHash = strings.TrimSpace(trace.UAHash)
}
}
}
if traceID == "" {
traceID = "sora-" + soraHashForLog(fmt.Sprintf("%s|%d", proxyKey, time.Now().UnixNano()))
}
return traceID, proxyKey, uaHash
}
func soraHashForLog(raw string) string {
h := fnv.New32a()
_, _ = h.Write([]byte(raw))
return fmt.Sprintf("%08x", h.Sum32())
}
func sanitizeSoraLogURL(raw string) string {
parsed, err := url.Parse(raw)
if err != nil {

111
backend/internal/service/sora_client_test.go
View File

@@ -833,7 +833,7 @@ func TestSoraDirectClient_DoHTTP_SidecarSessionKeyStableForSameAccountProxy(t *t
require.Equal(t, captured[0].SessionKey, captured[1].SessionKey)
}
func TestSoraDirectClient_DoRequestWithProxy_CloudflareChallengeSetsCooldownAndSkipsRetry(t *testing.T) {
func TestSoraDirectClient_DoRequestWithProxy_CloudflareChallengeSetsCooldownAfterSingleRetry(t *testing.T) {
var sidecarCalls int32
sidecar := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
atomic.AddInt32(&sidecarCalls, 1)
@@ -879,7 +879,7 @@ func TestSoraDirectClient_DoRequestWithProxy_CloudflareChallengeSetsCooldownAndS
var upstreamErr *SoraUpstreamError
require.ErrorAs(t, err, &upstreamErr)
require.Equal(t, http.StatusForbidden, upstreamErr.StatusCode)
require.Equal(t, int32(1), atomic.LoadInt32(&sidecarCalls), "challenge should not trigger retry loop")
require.Equal(t, int32(2), atomic.LoadInt32(&sidecarCalls), "challenge should trigger exactly one same-proxy retry")
_, _, err = client.doRequestWithProxy(
context.Background(),
@@ -896,7 +896,112 @@ func TestSoraDirectClient_DoRequestWithProxy_CloudflareChallengeSetsCooldownAndS
require.Equal(t, http.StatusTooManyRequests, upstreamErr.StatusCode)
require.Contains(t, upstreamErr.Message, "cooling down")
require.Contains(t, upstreamErr.Message, "cf-ray")
require.Equal(t, int32(1), atomic.LoadInt32(&sidecarCalls), "cooldown should block outbound request")
require.Equal(t, int32(2), atomic.LoadInt32(&sidecarCalls), "cooldown should block outbound request")
}
func TestSoraDirectClient_DoRequestWithProxy_CloudflareRetrySuccessClearsCooldown(t *testing.T) {
var sidecarCalls int32
sidecar := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
call := atomic.AddInt32(&sidecarCalls, 1)
if call == 1 {
_ = json.NewEncoder(w).Encode(map[string]any{
"status_code": http.StatusForbidden,
"headers": map[string]any{
"cf-ray": "9d05d73dec4d8c8e-GRU",
"content-type": "text/html",
},
"body": `<!DOCTYPE html><html><head><title>Just a moment...</title></head><body><script>window._cf_chl_opt={};</script></body></html>`,
})
return
}
_ = json.NewEncoder(w).Encode(map[string]any{
"status_code": http.StatusOK,
"headers": map[string]any{
"content-type": "application/json",
},
"body": `{"ok":true}`,
})
}))
defer sidecar.Close()
cfg := &config.Config{
Sora: config.SoraConfig{
Client: config.SoraClientConfig{
BaseURL: "https://sora.chatgpt.com/backend",
MaxRetries: 3,
CloudflareChallengeCooldownSeconds: 60,
CurlCFFISidecar: config.SoraCurlCFFISidecarConfig{
Enabled: true,
BaseURL: sidecar.URL,
Impersonate: "chrome131",
},
},
},
}
client := NewSoraDirectClient(cfg, nil, nil)
headers := http.Header{}
account := &Account{ID: 109}
proxyURL := "http://127.0.0.1:18080"
body, _, err := client.doRequestWithProxy(
context.Background(),
account,
proxyURL,
http.MethodGet,
"https://sora.chatgpt.com/backend/me",
headers,
nil,
true,
)
require.NoError(t, err)
require.Contains(t, string(body), `"ok":true`)
require.Equal(t, int32(2), atomic.LoadInt32(&sidecarCalls))
_, _, err = client.doRequestWithProxy(
context.Background(),
account,
proxyURL,
http.MethodGet,
"https://sora.chatgpt.com/backend/me",
headers,
nil,
true,
)
require.NoError(t, err)
require.Equal(t, int32(3), atomic.LoadInt32(&sidecarCalls), "cooldown should be cleared after retry succeeds")
}
func TestSoraComputeChallengeCooldownSeconds(t *testing.T) {
require.Equal(t, 0, soraComputeChallengeCooldownSeconds(0, 3))
require.Equal(t, 10, soraComputeChallengeCooldownSeconds(10, 1))
require.Equal(t, 20, soraComputeChallengeCooldownSeconds(10, 2))
require.Equal(t, 40, soraComputeChallengeCooldownSeconds(10, 4))
require.Equal(t, 40, soraComputeChallengeCooldownSeconds(10, 9), "streak should cap at x4")
require.Equal(t, 3600, soraComputeChallengeCooldownSeconds(1200, 9), "cooldown should cap at 3600s")
}
func TestSoraDirectClient_RecordCloudflareChallengeCooldown_EscalatesStreak(t *testing.T) {
cfg := &config.Config{
Sora: config.SoraConfig{
Client: config.SoraClientConfig{
CloudflareChallengeCooldownSeconds: 10,
},
},
}
client := NewSoraDirectClient(cfg, nil, nil)
account := &Account{ID: 201}
proxyURL := "http://127.0.0.1:18080"
client.recordCloudflareChallengeCooldown(account, proxyURL, http.StatusForbidden, http.Header{"Cf-Ray": []string{"9d05d73dec4d8c8e-GRU"}}, nil)
client.recordCloudflareChallengeCooldown(account, proxyURL, http.StatusForbidden, http.Header{"Cf-Ray": []string{"9d05d73dec4d8c8f-GRU"}}, nil)
key := soraAccountProxyKey(account, proxyURL)
entry, ok := client.challengeCooldowns[key]
require.True(t, ok)
require.Equal(t, 2, entry.ConsecutiveChallenges)
require.Equal(t, "9d05d73dec4d8c8f-GRU", entry.CFRay)
remain := int(entry.Until.Sub(entry.LastChallengeAt).Seconds())
require.GreaterOrEqual(t, remain, 19)
}
func TestSoraDirectClient_SidecarSessionKey_SkipsWhenAccountMissing(t *testing.T) {

69
backend/internal/service/sora_request_guard.go
View File

@@ -13,9 +13,11 @@ import (
)
type soraChallengeCooldownEntry struct {
Until time.Time
StatusCode int
CFRay string
Until time.Time
StatusCode int
CFRay string
ConsecutiveChallenges int
LastChallengeAt time.Time
}
type soraSidecarSessionEntry struct {
@@ -67,6 +69,9 @@ func (c *SoraDirectClient) checkCloudflareChallengeCooldown(account *Account, pr
remaining = 1
}
message := fmt.Sprintf("Sora request cooling down due to recent Cloudflare challenge. Retry in %d seconds.", remaining)
if entry.ConsecutiveChallenges > 1 {
message = fmt.Sprintf("%s (streak=%d)", message, entry.ConsecutiveChallenges)
}
if entry.CFRay != "" {
message = fmt.Sprintf("%s (last cf-ray: %s)", message, entry.CFRay)
}
@@ -90,22 +95,33 @@ func (c *SoraDirectClient) recordCloudflareChallengeCooldown(account *Account, p
}
key := soraAccountProxyKey(account, proxyURL)
now := time.Now()
until := now.Add(time.Duration(cooldownSeconds) * time.Second)
cfRay := soraerror.ExtractCloudflareRayID(headers, body)
c.challengeCooldownMu.Lock()
c.cleanupExpiredChallengeCooldownsLocked(now)
streak := 1
existing, ok := c.challengeCooldowns[key]
if ok && now.Sub(existing.LastChallengeAt) <= 30*time.Minute {
streak = existing.ConsecutiveChallenges + 1
}
effectiveCooldown := soraComputeChallengeCooldownSeconds(cooldownSeconds, streak)
until := now.Add(time.Duration(effectiveCooldown) * time.Second)
if ok && existing.Until.After(until) {
until = existing.Until
if existing.ConsecutiveChallenges > streak {
streak = existing.ConsecutiveChallenges
}
if cfRay == "" {
cfRay = existing.CFRay
}
}
c.challengeCooldowns[key] = soraChallengeCooldownEntry{
Until: until,
StatusCode: statusCode,
CFRay: cfRay,
Until: until,
StatusCode: statusCode,
CFRay: cfRay,
ConsecutiveChallenges: streak,
LastChallengeAt: now,
}
c.challengeCooldownMu.Unlock()
@@ -114,7 +130,44 @@ func (c *SoraDirectClient) recordCloudflareChallengeCooldown(account *Account, p
if remain < 0 {
remain = 0
}
c.debugLogf("cloudflare_challenge_cooldown_set key=%s status=%d remain_s=%d cf_ray=%s", key, statusCode, remain, cfRay)
c.debugLogf("cloudflare_challenge_cooldown_set key=%s status=%d remain_s=%d streak=%d cf_ray=%s", key, statusCode, remain, streak, cfRay)
}
}
func soraComputeChallengeCooldownSeconds(baseSeconds, streak int) int {
if baseSeconds <= 0 {
return 0
}
if streak < 1 {
streak = 1
}
multiplier := streak
if multiplier > 4 {
multiplier = 4
}
cooldown := baseSeconds * multiplier
if cooldown > 3600 {
cooldown = 3600
}
return cooldown
}
func (c *SoraDirectClient) clearCloudflareChallengeCooldown(account *Account, proxyURL string) {
if c == nil {
return
}
if account == nil || account.ID <= 0 {
return
}
key := soraAccountProxyKey(account, proxyURL)
c.challengeCooldownMu.Lock()
_, existed := c.challengeCooldowns[key]
if existed {
delete(c.challengeCooldowns, key)
}
c.challengeCooldownMu.Unlock()
if existed && c.debugEnabled() {
c.debugLogf("cloudflare_challenge_cooldown_cleared key=%s", key)
}
}