diff --git a/changelog/unreleased/worker-stream-timeout.md b/changelog/unreleased/worker-stream-timeout.md new file mode 100644 index 00000000..b09c0207 --- /dev/null +++ b/changelog/unreleased/worker-stream-timeout.md @@ -0,0 +1,11 @@ +### English + +- Stop streaming chat from hanging on a stuck upstream. A Qoder stream request whose first byte never arrives (the symptom was `qwen3.8-flash` requests with only an entry log line and no `chat reasoning resolved`) now fails fast after a 30-second TTFB deadline, classifies as `first_byte_timeout` / `unavailable` with failover, and is retried on the next eligible account instead of hanging the client until it gives up. The deadline is on the response head only — once headers arrive, the SSE body streams under the request's normal lifetime, so long thinking-model output is not cut off. +- Give the worker daemon its own upstream timeout. The worker's `fetch` to the Qoder gateway previously had no `AbortSignal`, so a stalled upstream held the worker's in-flight slot forever. It now aborts on a 30-second first-byte deadline, plus a mid-stream stall watchdog that fires only after 300 seconds of silence between chunks (it resets on every chunk, so a long but steady thinking stream is never truncated), returning a stable `first_byte_timeout` / `stream_total_timeout` error so the Go side can classify and fail over. Both are tunable via `QODER_STREAM_TTFB_MS` / `QODER_STREAM_TOTAL_MS`. +- Add a worker liveness watchdog to the maintenance loop. Health probes previously ran only at boot plus on manual console refresh, so a worker that stayed "alive" as a process but stopped serving `/health` was never noticed and kept being routed to. Every 30-second tick now issues one lightweight `/health` round-trip per worker account; three consecutive failures (~90s grace, enough to ride out a transient blip) restart the worker through the existing recovery path with backoff. A worker that answers but is still starting, rewarming, or waiting for login (`ready=false`) is treated as alive, so warming accounts are not rebooted. In-process accounts (WorkBuddy / Trae / Devin) are skipped and unaffected. + +### 中文 + +- 流式 chat 不再因上游卡死而无响应地挂起。Qoder 流式请求如果首字节迟迟不到(现象是 `qwen3.8-flash` 请求只有入口日志、没有 `chat reasoning resolved` 出口日志),现在会在 30 秒 TTFB 阈值后快速失败,归类为 `first_byte_timeout` / `unavailable` 并触发 failover,切到下一个可用账号重试,而不是把客户端挂到自行超时。该超时只针对响应头:一旦头部到达,SSE body 回到请求原本的生命周期,长思考模型的输出不会被截断。 +- 给 worker 守护进程加上自己的上游超时。worker 对 Qoder 网关的 `fetch` 此前没有 `AbortSignal`,上游停滞时会永久占用 worker 的并发槽。现在它在 30 秒首字节超时,以及"连续 300 秒没有新数据"的中途停滞看门狗(每收到一个 chunk 就重置,所以长但持续输出的思考流不会被截断)任一触发时 abort,返回稳定的 `first_byte_timeout` / `stream_total_timeout` 错误,让 Go 侧分类并 failover。两者均可通过 `QODER_STREAM_TTFB_MS` / `QODER_STREAM_TOTAL_MS` 调整。 +- 给维护循环加 worker liveness 看门狗。健康探针此前只在启动时和手动控制台刷新时跑,所以一个"进程还活着但 `/health` 不再响应"的 worker 永远不会被察觉,还会继续被路由命中。现在每 30 秒维护周期对每个 worker 账号发一次轻量 `/health` 探针;连续 3 次失败(约 90 秒容忍窗口,足以扛过瞬时抖动)就通过既有的恢复路径按退避重启该 worker。对 `/health` 有响应但仍在启动、rewarm 或等待登录(`ready=false`)的 worker 视为存活,不会误杀。进程内账号(WorkBuddy / Trae / Devin)被跳过,不受影响。 diff --git a/internal/executor/classify_test.go b/internal/executor/classify_test.go index c2ab5ad6..61e4a92c 100644 --- a/internal/executor/classify_test.go +++ b/internal/executor/classify_test.go @@ -320,3 +320,33 @@ func TestClassifyErrorUpstreamEmptyNoCooldown(t *testing.T) { t.Errorf("expected generic unavailable to keep cooldown, got %v", generic.Cooldown) } } + +// A streaming first-byte timeout is an upstream hang: the client request is +// still alive, the upstream just never sent a response head. It must classify +// as upstream_unavailable with failover so the next eligible account serves +// the turn, plus a short cooldown to shed a stuck worker for a few seconds. +func TestClassifyErrorFirstByteTimeoutFailsOver(t *testing.T) { + err := fmt.Errorf("%w: no response head within 1m0s", providers.ErrFirstByteTimeout) + got := ClassifyError(err) + if got.Kind != accounts.KindUnavailable { + t.Fatalf("Kind=%s, want %s", got.Kind, accounts.KindUnavailable) + } + if !got.Failover { + t.Fatalf("Failover=false, want true") + } + if got.Cooldown != 10*time.Second || got.RetryAfter != 10*time.Second { + t.Fatalf("Cooldown=%s RetryAfter=%s, want 10s", got.Cooldown, got.RetryAfter) + } + if got.Code != "first_byte_timeout" { + t.Fatalf("Code=%q, want first_byte_timeout", got.Code) + } +} + +// A plain client cancel must not be reclassified as a first-byte timeout; the +// executor skips failover and cooldown for cancellations. +func TestClassifyErrorContextCanceledStaysCanceled(t *testing.T) { + got := ClassifyError(context.Canceled) + if got.Kind != accounts.KindCanceled || got.Failover { + t.Fatalf("got Kind=%s Failover=%v, want %s/false", got.Kind, got.Failover, accounts.KindCanceled) + } +} diff --git a/internal/executor/error.go b/internal/executor/error.go index 66f49f26..458f354e 100644 --- a/internal/executor/error.go +++ b/internal/executor/error.go @@ -3,6 +3,7 @@ package executor import ( "context" "errors" + "net/http" "strings" "time" @@ -88,6 +89,17 @@ func ClassifyError(err error) Classified { if errors.As(err, &execErr) && execErr != nil { return execErr.Classified } + // A streaming first-byte timeout is an upstream hang, not a client cancel: + // the parent request is still alive, the upstream just never answered. Cool + // the account briefly and fail over so the next eligible account serves the + // turn instead of hanging until the client gives up. + if errors.Is(err, providers.ErrFirstByteTimeout) { + return Classified{ + Kind: accounts.KindUnavailable, Status: http.StatusBadGateway, + Failover: true, Cooldown: 10 * time.Second, RetryAfter: 10 * time.Second, + Code: "first_byte_timeout", Message: err.Error(), + } + } if errors.Is(err, context.Canceled) || errors.Is(err, context.DeadlineExceeded) { return Classified{ Kind: accounts.KindCanceled, Status: 499, Failover: false, diff --git a/internal/providers/interfaces.go b/internal/providers/interfaces.go index c5fa7fb9..33dd4569 100644 --- a/internal/providers/interfaces.go +++ b/internal/providers/interfaces.go @@ -15,6 +15,14 @@ import ( // implicit support. var ErrUnsupported = errors.New("provider capability unsupported") +// ErrFirstByteTimeout is returned by streaming chat adapters when the upstream +// did not send the response head (headers + first byte) within the TTFB +// deadline. The executor classifies it as upstream_unavailable with failover so +// the next eligible account is tried, instead of hanging on a stuck upstream. +// It must not be wrapped with context.DeadlineExceeded, or the executor would +// re-classify it as a client cancellation and skip failover. +var ErrFirstByteTimeout = errors.New("first byte timeout") + type ModelCapabilities struct { ContextWindow int `json:"context_window,omitempty"` ContextWindowMax int `json:"context_window_max,omitempty"` diff --git a/internal/providers/qoder/adapter.go b/internal/providers/qoder/adapter.go index 9c736f23..3032c480 100644 --- a/internal/providers/qoder/adapter.go +++ b/internal/providers/qoder/adapter.go @@ -35,6 +35,11 @@ type Client struct { loginTimeout time.Duration loginInterval time.Duration + // firstByteTimeout bounds how long the worker-path ChatStream waits for the + // upstream response head before failing over. Resolved from + // QODER_STREAM_TTFB_MS at construction; zero falls back to the default. + firstByteTimeout time.Duration + // direct is the in-process chat path. When set, chat does not enter the // per-account Node worker. Login, catalog, and quota still use that worker. direct *Direct @@ -42,13 +47,14 @@ type Client struct { func NewClient() *Client { return &Client{ - modelsHTTP: &http.Client{Timeout: 15 * time.Second}, - healthHTTP: &http.Client{Timeout: 2 * time.Second}, - quotaHTTP: &http.Client{Timeout: 5 * time.Second}, - adminHTTP: &http.Client{Timeout: 120 * time.Second}, - chatHTTP: &http.Client{Timeout: 120 * time.Second}, - loginTimeout: 90 * time.Second, - loginInterval: 200 * time.Millisecond, + modelsHTTP: &http.Client{Timeout: 15 * time.Second}, + healthHTTP: &http.Client{Timeout: 2 * time.Second}, + quotaHTTP: &http.Client{Timeout: 5 * time.Second}, + adminHTTP: &http.Client{Timeout: 120 * time.Second}, + chatHTTP: &http.Client{Timeout: 120 * time.Second}, + loginTimeout: 90 * time.Second, + loginInterval: 200 * time.Millisecond, + firstByteTimeout: resolveFirstByteTimeout(), } } @@ -537,6 +543,7 @@ func (c *Client) ChatStream(ctx context.Context, accountID string, req translate } c.mu.RLock() httpClient := c.chatHTTP + firstByte := c.firstByteTimeout c.mu.RUnlock() if httpClient == nil { httpClient = http.DefaultClient @@ -546,9 +553,9 @@ func (c *Client) ChatStream(ctx context.Context, accountID string, req translate cloned.Timeout = 0 httpClient = &cloned } - resp, err := httpClient.Do(httpReq) + resp, err := doWithFirstByteTimeout(httpClient, httpReq, firstByte) if err != nil { - return nil, providers.ResolvedChat{}, TransportError{Err: err} + return nil, providers.ResolvedChat{}, err } return resp, resolved, nil } diff --git a/internal/providers/qoder/direct.go b/internal/providers/qoder/direct.go index 718ef3c3..d63251d5 100644 --- a/internal/providers/qoder/direct.go +++ b/internal/providers/qoder/direct.go @@ -24,6 +24,9 @@ type Direct struct { region func(ctx context.Context, accountID string) (string, error) http *http.Client now func() time.Time + // ttfb bounds how long ChatStream waits for the upstream response head. + // Zero falls back to defaultFirstByteTimeout inside doWithFirstByteTimeout. + ttfb time.Duration } func NewDirect(store CredentialStore, region func(context.Context, string) (string, error)) *Direct { @@ -32,6 +35,7 @@ func NewDirect(store CredentialStore, region func(context.Context, string) (stri region: region, http: &http.Client{}, now: time.Now, + ttfb: resolveFirstByteTimeout(), } } @@ -128,7 +132,7 @@ func (d *Direct) ChatStream(ctx context.Context, accountID string, req translate if err != nil { return nil, providers.ResolvedChat{}, err } - resp, err := d.http.Do(prepared.request) + resp, err := doWithFirstByteTimeout(d.http, prepared.request, d.ttfb) if err != nil { return nil, providers.ResolvedChat{}, err } diff --git a/internal/providers/qoder/first_byte_timeout_test.go b/internal/providers/qoder/first_byte_timeout_test.go new file mode 100644 index 00000000..59a996b4 --- /dev/null +++ b/internal/providers/qoder/first_byte_timeout_test.go @@ -0,0 +1,110 @@ +package qoder + +import ( + "bytes" + "context" + "errors" + "io" + "net/http" + "net/http/httptest" + "strings" + "testing" + "time" + + "github.com/caigee-cmd/cli2api/internal/providers" +) + +// A stuck upstream that never sends the response head must surface as +// ErrFirstByteTimeout so the executor can fail the attempt over instead of +// hanging the client until it gives up. The production deadline is shrunk for +// the test so the assertion runs in milliseconds. +func TestDoWithFirstByteTimeoutHangsAsFirstByteTimeout(t *testing.T) { + // Handler blocks forever: it accepts the body but never writes a response. + hung := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + <-r.Context().Done() + })) + t.Cleanup(hung.Close) + + req, err := http.NewRequestWithContext(context.Background(), http.MethodPost, hung.URL, nil) + if err != nil { + t.Fatalf("NewRequest: %v", err) + } + client := &http.Client{Timeout: 0} // mimic streaming client: no whole-call timeout + _, err = doWithFirstByteTimeout(client, req, 50*time.Millisecond) + if !errors.Is(err, providers.ErrFirstByteTimeout) { + t.Fatalf("want ErrFirstByteTimeout, got %v", err) + } +} + +// When the parent context is already cancelled the helper must propagate the +// plain transport error instead of masking it as a first-byte timeout; the +// executor classifies client cancels as KindCanceled (no failover, no cooldown). +func TestDoWithFirstByteTimeoutParentCancelIsNotFirstByteTimeout(t *testing.T) { + hung := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + <-r.Context().Done() + })) + t.Cleanup(hung.Close) + + ctx, cancel := context.WithCancel(context.Background()) + req, err := http.NewRequestWithContext(ctx, http.MethodPost, hung.URL, nil) + if err != nil { + t.Fatalf("NewRequest: %v", err) + } + client := &http.Client{Timeout: 0} + + // Cancel before the call so parent.Err() is non-nil at the point of failure. + cancel() + _, err = doWithFirstByteTimeout(client, req, 50*time.Millisecond) + if errors.Is(err, providers.ErrFirstByteTimeout) { + t.Fatalf("parent-cancelled call must not surface as ErrFirstByteTimeout, got %v", err) + } + if err == nil { + t.Fatalf("want non-nil error for cancelled parent context") + } +} + +// A well-behaved upstream that returns a response head quickly must not be +// cut off by the TTFB timer, and the whole multi-chunk body must stay readable +// to EOF afterwards. This drains every chunk rather than doing a single buffered +// Read: a cancel-on-return bug only shows up once the stream continues past the +// first read, which is exactly the "dies right after headers" symptom. +func TestDoWithFirstByteTimeoutStreamsBodyToEOF(t *testing.T) { + const chunks = 4 + ok := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header().Set("content-type", "text/event-stream") + w.WriteHeader(http.StatusOK) + flusher, _ := w.(http.Flusher) + for i := 0; i < chunks; i++ { + _, _ = w.Write([]byte("data: chunk\n\n")) + if flusher != nil { + flusher.Flush() + } + // Space the chunks out so the first-byte deadline would fire if the + // timer were not stopped and the context were cancelled on return. + time.Sleep(20 * time.Millisecond) + } + })) + t.Cleanup(ok.Close) + + req, err := http.NewRequestWithContext(context.Background(), http.MethodPost, ok.URL, nil) + if err != nil { + t.Fatalf("NewRequest: %v", err) + } + client := &http.Client{Timeout: 0} + // Short TTFB deadline: the head arrives immediately, so a correct + // implementation stops the timer and never cancels the body. + resp, err := doWithFirstByteTimeout(client, req, 50*time.Millisecond) + if err != nil { + t.Fatalf("want nil err for fast head, got %v", err) + } + defer resp.Body.Close() + + var got bytes.Buffer + if _, err := io.Copy(&got, resp.Body); err != nil { + t.Fatalf("drain body to EOF: %v (read %q)", err, got.String()) + } + want := strings.Repeat("data: chunk\n\n", chunks) + if got.String() != want { + t.Fatalf("body = %q, want %q", got.String(), want) + } +} diff --git a/internal/providers/qoder/worker.go b/internal/providers/qoder/worker.go index 20bd1f19..903555ad 100644 --- a/internal/providers/qoder/worker.go +++ b/internal/providers/qoder/worker.go @@ -8,11 +8,14 @@ import ( "fmt" "io" "net/http" + "os" + "strconv" "strings" "time" "github.com/caigee-cmd/cli2api/internal/accounts" "github.com/caigee-cmd/cli2api/internal/endpoint" + "github.com/caigee-cmd/cli2api/internal/providers" ) var ( @@ -49,6 +52,101 @@ func (e TransportError) Error() string { func (e TransportError) Unwrap() error { return e.Err } +// defaultFirstByteTimeout caps how long a streaming chat request will wait for +// the upstream response head (status + headers). Once the head arrives, the +// timer is stopped and the SSE body streams under the parent context's lifetime, +// so long thinking-model output is not cut off. A stuck upstream that never +// sends a first byte surfaces as ErrFirstByteTimeout so the executor can fail +// over to the next account instead of hanging forever. 30s covers slow +// cold-starts and thinking-model first-token latency while keeping a +// stuck-upstream failover inside one round-trip of the client's patience. +// +// The effective value is resolved once at construction (see +// resolveFirstByteTimeout) and can be tuned per deployment with +// QODER_STREAM_TTFB_MS, mirroring the worker daemon's own knob. +const defaultFirstByteTimeout = 30 * time.Second + +// resolveFirstByteTimeout reads QODER_STREAM_TTFB_MS, falling back to +// defaultFirstByteTimeout for an absent or invalid value. The floor matches the +// worker daemon's so the two deadlines cannot be configured to disagree wildly. +func resolveFirstByteTimeout() time.Duration { + raw := strings.TrimSpace(os.Getenv("QODER_STREAM_TTFB_MS")) + if raw == "" { + return defaultFirstByteTimeout + } + ms, err := strconv.Atoi(raw) + if err != nil || ms <= 0 { + return defaultFirstByteTimeout + } + d := time.Duration(ms) * time.Millisecond + if d < 5*time.Second { + return 5 * time.Second + } + return d +} + +// doWithFirstByteTimeout sends req with client, returning a response once the +// response head is received. If the head does not arrive within timeout it +// returns an error wrapping providers.ErrFirstByteTimeout; if the parent +// context was already cancelled it surfaces that error unchanged so the +// executor classifies it as a client cancellation rather than a timeout. +// +// The TTFB context must NOT be cancelled once the head arrives: Go's HTTP +// client ties the response body to the request context, so cancelling would +// kill the body mid-stream (the SSE read then fails with "context canceled" +// after the head was already delivered). Only the error path cancels; on +// success the deadline goroutine is stopped and the body lives under the +// parent context, with the response body's Close as the eventual release. +func doWithFirstByteTimeout(client *http.Client, req *http.Request, timeout time.Duration) (*http.Response, error) { + if timeout <= 0 { + timeout = defaultFirstByteTimeout + } + parent := req.Context() + ttfbCtx, cancelTTFB := context.WithCancel(parent) + timer := time.AfterFunc(timeout, cancelTTFB) + resp, err := client.Do(req.WithContext(ttfbCtx)) + if err == nil { + // Head arrived: stop the timer but keep ttfbCtx alive so the body + // remains readable. Tie the cancel to Body.Close so the derived context + // is released exactly when the caller is done with the stream, while + // the parent context still governs its lifetime (client disconnect / + // shutdown). Cancelling here instead would kill the body mid-stream. + timer.Stop() + resp.Body = &cancelOnCloseBody{ReadCloser: resp.Body, cancel: cancelTTFB} + return resp, nil + } + timer.Stop() + // TTFB fired only when the parent context is still alive: a parent cancel + // (client disconnect, shutdown) must stay a plain cancel so the executor + // does not treat it as an upstream failure worth cooling down. Decide this + // before cancelTTFB below, which would otherwise make ttfbCtx.Err() non-nil + // regardless of the real cause. + timedOut := parent.Err() == nil && ttfbCtx.Err() != nil && !errors.Is(parent.Err(), context.Canceled) + cancelTTFB() + if timedOut { + return nil, fmt.Errorf("%w: no response head within %s", providers.ErrFirstByteTimeout, timeout) + } + return nil, TransportError{Err: err} +} + +// cancelOnCloseBody releases the TTFB-derived context when the caller closes +// the response body. The body itself is tied to that context by Go's HTTP +// client, so cancelling earlier would truncate the stream; cancelling on Close +// frees the timer goroutine's context exactly when the stream is finished. +type cancelOnCloseBody struct { + io.ReadCloser + cancel context.CancelFunc +} + +func (b *cancelOnCloseBody) Close() error { + err := b.ReadCloser.Close() + if b.cancel != nil { + b.cancel() + b.cancel = nil + } + return err +} + type HTTPStatusError struct { Op string Status int diff --git a/internal/runtime/manager.go b/internal/runtime/manager.go index 5437c75a..cb5bb696 100644 --- a/internal/runtime/manager.go +++ b/internal/runtime/manager.go @@ -127,6 +127,13 @@ type Manager struct { // account removal can race with the sweep. quotaProbeMu sync.Mutex quotaProbeLevels map[string]int + + // healthFailures counts consecutive liveness probe failures per worker + // account. The maintenance loop's workerLiveness watchdog increments it on + // each failed /health probe and clears it on success; reaching + // workerLivenessThreshold triggers a stopAccount so watchAccount + + // beginAccountRecovery reboot the stuck worker. Guarded by mu. + healthFailures map[string]int } func NewManager(config ManagerConfig, store AccountStore, starter ProcessStarter) *Manager { @@ -165,6 +172,7 @@ func NewManager(config ManagerConfig, store AccountStore, starter ProcessStarter persistCloseCh: make(chan struct{}), cpuPrev: map[int]procTime{}, quotaProbeLevels: map[string]int{}, + healthFailures: map[string]int{}, } manager.persistCond = sync.NewCond(&manager.persistMu) manager.persistDone.Add(1) diff --git a/internal/runtime/manager_maintenance.go b/internal/runtime/manager_maintenance.go index 8f9898d0..00f650fc 100644 --- a/internal/runtime/manager_maintenance.go +++ b/internal/runtime/manager_maintenance.go @@ -289,6 +289,10 @@ func (manager *Manager) RunMaintenanceLoop(stop <-chan struct{}) { // Seed the throttle so the first pass does not duplicate the boot-time // RefreshAll: the next stale-quota sweep runs 5 minutes after startup. lastStaleQuota := time.Now() + // Liveness probes start one tick in so boot-time RefreshAll owns the first + // /health round-trip and short-lived tests with a stub worker are not probed + // the instant the loop starts. + lastLiveness := time.Now() for { if ctx.Err() != nil { return @@ -303,6 +307,10 @@ func (manager *Manager) RunMaintenanceLoop(stop <-chan struct{}) { lastKeepaliveDay = day } manager.sampleResources() + if now.Sub(lastLiveness) >= 30*time.Second { + manager.probeWorkerLiveness(ctx) + lastLiveness = now + } if now.Sub(lastStaleQuota) >= staleQuotaInterval { manager.refreshStaleQuota(ctx) lastStaleQuota = now @@ -479,3 +487,79 @@ func (manager *Manager) pruneQuotaProbeLevels(seen map[string]struct{}) { } } } + +// workerLivenessThreshold is how many consecutive /health probe failures the +// watchdog tolerates before rebooting a stuck worker. At a 30s maintenance +// cadence that is roughly a 90s grace window: long enough to ride out a +// transient network blip or a worker mid-rewarm, short enough that a genuinely +// stuck process is recovered before clients notice repeated hangs. +const workerLivenessThreshold = 3 + +// probeWorkerLiveness is the worker-side watchdog. refreshOne and the boot-time +// RefreshAll only run at startup and on manual console refresh, so a worker +// that goes "alive but stuck" after boot — /health no longer responds, or its +// goroutine is wedged — would stay routed to forever without this loop. Each +// 30s tick issues one /health round-trip per worker account; on the +// threshold-th consecutive failure it calls stopAccount so the existing +// watchAccount + beginAccountRecovery path reboots the worker with backoff. +// +// In-process accounts are skipped by probeHealthOnly and never enter the +// failure counter, so WorkBuddy / Trae / Devin are unaffected. +func (manager *Manager) probeWorkerLiveness(ctx context.Context) { + for _, item := range manager.pool.Items() { + if item.RuntimeState == "dead" { + continue + } + ready, err := manager.probeHealthOnly(ctx, item) + if err == nil && ready { + manager.mu.Lock() + delete(manager.healthFailures, item.ID) + manager.mu.Unlock() + continue + } + // Skip accounts already in recovery: stopAccount removed them from + // processes and beginAccountRecovery owns the reboot. Touching them + // here would double-restart or race the recovering guard. + manager.mu.Lock() + if manager.recovering[item.ID] { + manager.mu.Unlock() + continue + } + manager.healthFailures[item.ID]++ + fails := manager.healthFailures[item.ID] + manager.mu.Unlock() + if fails >= workerLivenessThreshold { + log.Printf("worker liveness: account %s failed %d consecutive health probes (%v); restarting", + item.ID, fails, err) + manager.mu.Lock() + delete(manager.healthFailures, item.ID) + manager.mu.Unlock() + manager.restartStuckWorker(item.ID, err) + } + } +} + +// restartStuckWorker reboots a worker whose /health stopped answering. It must +// not simply call stopAccount: stopAccount deletes m.processes[id] before +// Stop(), so watchAccount later sees a process mismatch and returns without +// calling beginAccountRecovery — the stuck worker would become a permanently +// dead account. Instead detach the process from the table (so watchAccount +// cannot also recover it), stop it, then hand it to beginAccountRecovery +// directly, which owns the backoff restart. +func (manager *Manager) restartStuckWorker(id string, probeErr error) { + manager.mu.Lock() + process := manager.processes[id] + delete(manager.processes, id) + manager.mu.Unlock() + manager.pool.Remove(id) + if process != nil { + if perr := process.Stop(); perr != nil { + log.Printf("worker liveness: stop %s failed: %v", id, perr) + } + } + reason := "worker liveness probe failed" + if probeErr != nil { + reason = "worker liveness probe failed: " + probeErr.Error() + } + manager.beginAccountRecovery(id, errors.New(reason)) +} diff --git a/internal/runtime/manager_probe.go b/internal/runtime/manager_probe.go index 68191600..85778703 100644 --- a/internal/runtime/manager_probe.go +++ b/internal/runtime/manager_probe.go @@ -148,3 +148,38 @@ func (m *Manager) forceReady(accountID string) bool { _, err := os.Stat(filepath.Join(m.config.DataDir, "force-ready", accountID)) return err == nil } + +// probeHealthOnly issues a single GET /health to a worker account with a tight +// 2s deadline. It is the liveness probe used by the maintenance-loop watchdog: +// unlike refreshOne, it does not fetch quota or refresh the model catalog, so a +// 30s-loop call costs one HTTP round-trip, not a quota probe. The pool state +// machine is left to refreshOne and the manual console refresh path; this only +// decides whether the worker process is still alive enough to serve at all. +// +// "Alive" is deliberately loose: a transport error or a non-2xx / non-ok status +// means the process is wedged or gone and worth rebooting, but a 200 with +// ready=false is NOT a failure. A worker that is still starting, rewarming, or +// waiting for login answers /health with ok=true, ready=false — killing it after +// ~90s would loop a healthy-but-warming account. readiness stays refreshOne's +// job; only the daemon being unreachable or unhealthy counts here. +// +// In-process accounts (WorkBuddy / Trae / Devin) have no child-process /health +// endpoint and never need this check — their liveness is the adapter's own +// transport, which the executor already classifies. probeHealthOnly returns +// (true, nil) for them so the watchdog skips them. +func (m *Manager) probeHealthOnly(ctx context.Context, item Item) (bool, error) { + if item.Runtime == string(providers.RuntimeInProcess) || strings.TrimSpace(item.URL) == "" { + return true, nil + } + probeCtx, cancel := context.WithTimeout(ctx, 2*time.Second) + defer cancel() + client := qoder.WorkerClient{HTTP: m.httpClient} + health, statusCode, err := client.Health(probeCtx, item.URL) + if err != nil { + return false, err + } + if statusCode >= 300 || !health.OK { + return false, nil + } + return true, nil +} diff --git a/internal/runtime/probe_worker_liveness_test.go b/internal/runtime/probe_worker_liveness_test.go new file mode 100644 index 00000000..85694932 --- /dev/null +++ b/internal/runtime/probe_worker_liveness_test.go @@ -0,0 +1,213 @@ +package runtime + +import ( + "context" + "net/http" + "net/http/httptest" + "path/filepath" + "strconv" + "testing" + "time" + + "github.com/caigee-cmd/cli2api/internal/accounts" + sqlstore "github.com/caigee-cmd/cli2api/internal/store" +) + +// livenessProcess is a minimal ManagedProcess for the watchdog test: its URL +// points at an unlistened port so probeHealthOnly's /health round-trip fails on +// transport, and Stop records that it was invoked. +type livenessProcess struct { + url string + stopped bool + done chan error +} + +func (p *livenessProcess) URL() string { return p.url } +func (p *livenessProcess) Done() <-chan error { return p.done } +func (p *livenessProcess) PID() int { return 0 } +func (p *livenessProcess) Stop() error { + p.stopped = true + select { + case p.done <- nil: + default: + } + return nil +} + +type livenessStarter struct { + started chan *livenessProcess +} + +func (s *livenessStarter) Start(_ context.Context, _ accounts.Account, _ string, port int) (ManagedProcess, error) { + p := &livenessProcess{ + url: "http://127.0.0.1:" + strconv.Itoa(port), + done: make(chan error, 1), + } + s.started <- p + return p, nil +} + +// A worker whose /health never answers (the starter URL points at an +// unlistened port) must be stopped AND handed to recovery after the liveness +// threshold of consecutive probe failures. This is the watchdog path for a +// worker that stays "alive" as a process but stops serving; recovery must +// spawn a replacement process, otherwise the stuck account is permanently dead. +func TestProbeWorkerLivenessRestartsStuckWorker(t *testing.T) { + ctx := context.Background() + dataDir := t.TempDir() + store, err := sqlstore.OpenStore(filepath.Join(dataDir, "qoder.db")) + if err != nil { + t.Fatal(err) + } + defer store.Close() + account, err := store.Create(ctx, accounts.CreateAccount{Name: "stuck", Enabled: true, MaxInFlight: 3}) + if err != nil { + t.Fatal(err) + } + credential := accounts.NativeCredential{UserBlob: []byte("ciphertext"), MachineID: "machine-1"} + if err := store.SaveCredential(ctx, account.ID, "native", credential); err != nil { + t.Fatal(err) + } + starter := &livenessStarter{started: make(chan *livenessProcess, 4)} + manager := NewManager(ManagerConfig{ + DataDir: dataDir, + BasePort: 32500, + RestartDelay: 50 * time.Millisecond, + }, store, starter) + if err := manager.Start(ctx); err != nil { + t.Fatal(err) + } + defer manager.Close() + + var proc *livenessProcess + select { + case proc = <-starter.started: + case <-time.After(2 * time.Second): + t.Fatal("starter was not invoked") + } + + // Threshold consecutive failures must trigger stopAccount. The account's + // /health URL is not serving, so every probe fails on transport. + for i := 1; i <= 3; i++ { + manager.probeWorkerLiveness(ctx) + } + if !proc.stopped { + t.Fatalf("want stuck worker stopped after %d probe failures, got stopped=%v", 3, proc.stopped) + } + // The failure counter is cleared once a restart is issued so recovery does + // not inherit a stale count. + manager.mu.Lock() + got := manager.healthFailures[account.ID] + manager.mu.Unlock() + if got != 0 { + t.Fatalf("healthFailures after stop = %d, want 0", got) + } + // Recovery must actually start a replacement process: the old bug deleted + // m.processes[id] before Stop(), so watchAccount saw a mismatch and returned + // without beginAccountRecovery, leaving the account permanently dead. + select { + case replacement := <-starter.started: + if replacement == proc { + t.Fatalf("recovery reused the stuck process instead of starting a new one") + } + case <-time.After(2 * time.Second): + t.Fatal("watchdog stopped the stuck worker but never restarted it") + } +} + +// A transient failure must not restart the worker: only the threshold-th +// consecutive failure triggers stop. Two failures leave the counter +// incremented and the process running. +func TestProbeWorkerLivenessToleratesTransientFailures(t *testing.T) { + ctx := context.Background() + dataDir := t.TempDir() + store, err := sqlstore.OpenStore(filepath.Join(dataDir, "qoder.db")) + if err != nil { + t.Fatal(err) + } + defer store.Close() + account, err := store.Create(ctx, accounts.CreateAccount{Name: "flaky", Enabled: true, MaxInFlight: 3}) + if err != nil { + t.Fatal(err) + } + credential := accounts.NativeCredential{UserBlob: []byte("ciphertext"), MachineID: "machine-1"} + if err := store.SaveCredential(ctx, account.ID, "native", credential); err != nil { + t.Fatal(err) + } + starter := &livenessStarter{started: make(chan *livenessProcess, 4)} + manager := NewManager(ManagerConfig{ + DataDir: dataDir, + BasePort: 32600, + }, store, starter) + if err := manager.Start(ctx); err != nil { + t.Fatal(err) + } + defer manager.Close() + + var proc *livenessProcess + select { + case proc = <-starter.started: + case <-time.After(2 * time.Second): + t.Fatal("starter was not invoked") + } + + manager.probeWorkerLiveness(ctx) + manager.probeWorkerLiveness(ctx) + if proc.stopped { + t.Fatalf("worker must not be stopped before threshold, got stopped=true") + } + manager.mu.Lock() + got := manager.healthFailures[account.ID] + manager.mu.Unlock() + if got != 2 { + t.Fatalf("healthFailures = %d, want 2", got) + } +} + +// A worker that answers /health with ok=true but ready=false is still alive: +// it is starting, rewarming, or waiting for login. The liveness probe must not +// treat that as a failure, or the watchdog would reboot a healthy-but-warming +// account every ~90s. +func TestProbeHealthOnlyTreatsWarmingWorkerAsAlive(t *testing.T) { + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header().Set("content-type", "application/json") + _, _ = w.Write([]byte(`{"ok":true,"ready":false,"hot":false,"hasAuthManager":true}`)) + })) + t.Cleanup(srv.Close) + + manager := NewManager(ManagerConfig{DataDir: t.TempDir()}, nil, nil) + alive, err := manager.probeHealthOnly(context.Background(), Item{ + ID: "warming", + Runtime: "child_process", + URL: srv.URL, + }) + if err != nil { + t.Fatalf("probeHealthOnly: %v", err) + } + if !alive { + t.Fatalf("warming worker (ok=true, ready=false) must be treated as alive") + } +} + +// A 200 that reports ok=false is an unhealthy daemon and must count as a +// failure so it can be rebooted. +func TestProbeHealthOnlyTreatsUnhealthyAsDead(t *testing.T) { + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header().Set("content-type", "application/json") + _, _ = w.Write([]byte(`{"ok":false,"ready":false}`)) + })) + t.Cleanup(srv.Close) + + manager := NewManager(ManagerConfig{DataDir: t.TempDir()}, nil, nil) + alive, err := manager.probeHealthOnly(context.Background(), Item{ + ID: "unhealthy", + Runtime: "child_process", + URL: srv.URL, + }) + if err != nil { + t.Fatalf("probeHealthOnly: %v", err) + } + if alive { + t.Fatalf("ok=false daemon must be treated as dead") + } +} diff --git a/worker/src/daemon.mjs b/worker/src/daemon.mjs index 3651fa16..92c082b5 100644 --- a/worker/src/daemon.mjs +++ b/worker/src/daemon.mjs @@ -11,6 +11,7 @@ import { inspectQodercliSource, NEEDLES, PINNED_QODERCLI_VERSION, readQodercliVe import { resolveUsage } from "./usage.mjs"; import { classifyError } from "./errors.mjs"; import { createQoderCheckin } from "./checkin.mjs"; +import { fetchWithTimeout, streamStallMs } from "./upstream.mjs"; const __dirname = path.dirname(fileURLToPath(import.meta.url)); register(pathToFileURL(path.join(__dirname, "rewrite-loader.mjs")).href); @@ -137,7 +138,6 @@ let encodeChain = Promise.resolve(); let inFlight = 0; const maxInFlight = Math.max(1, Number(process.env.QODER_MAX_INFLIGHT || 4) || 4); - function sealContext(ctx) { try { ctx.free = function () { @@ -401,11 +401,15 @@ async function prepareUpstream(reqBody) { if (encoded?.headers?.forEach) encoded.headers.forEach((v, k) => (headers[k] = v)); else Object.assign(headers, encoded?.headers || {}); - const upstream = await fetch(encoded.url, { - method: "POST", - headers, - body: encoded.body, - }); + const upstream = await fetchWithTimeout( + encoded.url, + { + method: "POST", + headers, + body: encoded.body, + }, + { stallMs: streamStallMs }, + ); return { plain, upstream }; } diff --git a/worker/src/sse.mjs b/worker/src/sse.mjs index aa686dd1..d409196d 100644 --- a/worker/src/sse.mjs +++ b/worker/src/sse.mjs @@ -293,6 +293,11 @@ export async function pipeNestedSseToOpenAI(upstreamRes, res, { model = "auto", readResult = await reader.read(); } catch (err) { const detail = err?.message || String(err); + // Preserve a timeout code from the fetch wrapper (first_byte_timeout / + // stream_total_timeout) so a mid-stream stall is reported as a retryable + // upstream timeout, not a generic interrupt. The message still carries + // the original detail for diagnostics. + const code = err?.code || "upstream_stream_interrupted"; emitDiagnostic("read_error"); console.error("[sse] upstream stream read failed", { model, @@ -304,14 +309,14 @@ export async function pipeNestedSseToOpenAI(upstreamRes, res, { model = "auto", error: detail, }); writeStructuredStreamError(res, { - code: "upstream_stream_interrupted", + code, type: "api_error", kind: "unavailable", status: 502, failover: true, message: detail, }); - throw new Error(`upstream_stream_interrupted: ${detail}`); + throw new Error(`${code}: ${detail}`); } const { value, done } = readResult; let chunkText; diff --git a/worker/src/upstream.mjs b/worker/src/upstream.mjs new file mode 100644 index 00000000..3ff042b5 --- /dev/null +++ b/worker/src/upstream.mjs @@ -0,0 +1,95 @@ +// Upstream fetch with a first-byte deadline and a mid-stream stall watchdog. +// Extracted from daemon.mjs so it can be unit-tested without booting the CLI. + +// First-byte and mid-stream stall deadlines protect the worker from a stuck +// upstream: Qoder's SSE can hang at the head (TTFB) or stop sending data +// mid-stream when the gateway is degraded. The TTFB timer stops as soon as the +// response head arrives. The stall watchdog is NOT a wall-clock cap: it resets +// every time a chunk arrives, so a long thinking-model stream that keeps +// producing output is never truncated — only a stream that goes silent for the +// whole window is aborted. The TTFB default mirrors the Go-side first-byte +// deadline so worker and gateway agree on when a stuck head counts as a +// failure; both are tunable per deployment. +export const streamTtfbMs = Math.max(5_000, Number(process.env.QODER_STREAM_TTFB_MS || 30_000) || 30_000); +export const streamStallMs = Math.max(streamTtfbMs, Number(process.env.QODER_STREAM_TOTAL_MS || 300_000) || 300_000); + +// fetchWithTimeout wraps fetch with a TTFB deadline on the response head and +// (optionally) a mid-stream stall watchdog on the body. The TTFB timer fires +// only if the head has not arrived; once it does, the timer is cleared. The +// stall watchdog is attached to the body and only fires when no chunk has +// arrived for stallMs. When a deadline fires the rejection carries a stable +// `.code` (first_byte_timeout / stream_total_timeout) that the callers forward +// so the Go side can classify and fail over instead of seeing a bare abort. +export async function fetchWithTimeout(url, opts = {}, { ttfbMs = streamTtfbMs, stallMs = 0 } = {}) { + const controller = new AbortController(); + const abortWith = (code, message) => { + const err = new Error(message); + err.code = code; + controller.abort(err); + }; + const ttfbTimer = setTimeout(() => { + abortWith("first_byte_timeout", `upstream first-byte timeout after ${ttfbMs}ms`); + }, ttfbMs); + let resp; + try { + resp = await fetch(url, { ...opts, signal: controller.signal }); + } catch (err) { + clearTimeout(ttfbTimer); + // err carries .code when our own timer aborted; rethrow unchanged. + throw err; + } + clearTimeout(ttfbTimer); + if (stallMs > 0 && resp.body) attachStallWatchdog(resp, controller, stallMs); + return resp; +} + +// attachStallWatchdog replaces resp.body with a wrapper that arms a timer on +// each chunk and aborts the request when the stream goes silent for stallMs. +// The timer is cleared when the body ends, errors, or is cancelled, so it never +// outlives the request. Aborting the controller mid-stream makes the reader +// reject with the abort reason (code=stream_total_timeout), which the SSE pipe +// turns into a structured error event rather than a silent truncation. +export function attachStallWatchdog(resp, controller, stallMs) { + const original = resp.body; + if (!original) return; + const reader = original.getReader(); + let timer = null; + const disarm = () => { + if (timer) { + clearTimeout(timer); + timer = null; + } + }; + const arm = () => { + disarm(); + timer = setTimeout(() => { + const err = new Error(`upstream stream stalled for ${stallMs}ms`); + err.code = "stream_total_timeout"; + controller.abort(err); + }, stallMs); + if (typeof timer.unref === "function") timer.unref(); + }; + arm(); + const wrapped = new ReadableStream({ + async pull(ctrl) { + try { + const { done, value } = await reader.read(); + if (done) { + disarm(); + ctrl.close(); + return; + } + arm(); + ctrl.enqueue(value); + } catch (err) { + disarm(); + ctrl.error(err); + } + }, + cancel(reason) { + disarm(); + return reader.cancel(reason); + }, + }); + Object.defineProperty(resp, "body", { value: wrapped, configurable: true }); +} diff --git a/worker/test/upstream.test.mjs b/worker/test/upstream.test.mjs new file mode 100644 index 00000000..250c1d68 --- /dev/null +++ b/worker/test/upstream.test.mjs @@ -0,0 +1,83 @@ +import assert from "node:assert/strict"; +import http from "node:http"; +import { test } from "node:test"; +import { fetchWithTimeout } from "../src/upstream.mjs"; + +function listen(handler) { + return new Promise((resolve) => { + const server = http.createServer(handler); + server.listen(0, "127.0.0.1", () => resolve(server)); + }); +} + +function close(server) { + return new Promise((resolve) => server.close(resolve)); +} + +// A head that never arrives must reject with first_byte_timeout so the Go side +// can fail over instead of the worker holding its in-flight slot forever. +test("first-byte deadline aborts a stuck head", async () => { + const server = await listen(() => { + /* accept the request, never respond */ + }); + try { + const port = server.address().port; + await assert.rejects( + fetchWithTimeout(`http://127.0.0.1:${port}`, { method: "POST" }, { ttfbMs: 50 }), + (err) => err.code === "first_byte_timeout", + ); + } finally { + await close(server); + } +}); + +// A steady stream that keeps producing chunks must NOT be cut off, even when it +// runs longer than the stall window: the watchdog resets on every chunk. +test("stall watchdog does not truncate a steady stream", async () => { + const server = await listen((req, res) => { + res.writeHead(200, { "content-type": "text/event-stream" }); + let i = 0; + const timer = setInterval(() => { + res.write(`data: chunk-${i++}\n\n`); + if (i >= 8) { + clearInterval(timer); + res.end(); + } + }, 20); + }); + try { + const port = server.address().port; + const resp = await fetchWithTimeout(`http://127.0.0.1:${port}`, {}, { ttfbMs: 500, stallMs: 100 }); + const reader = resp.body.getReader(); + let chunks = 0; + while (true) { + const { done } = await reader.read(); + if (done) break; + chunks += 1; + } + // 8 interval writes over ~160ms with a 100ms stall window: a wall-clock cap + // would have aborted it; a per-chunk reset lets it finish. + assert.ok(chunks >= 1, `expected streamed chunks, got ${chunks}`); + } finally { + await close(server); + } +}); + +// A stream that goes silent mid-body must reject with stream_total_timeout so a +// truncated upstream surfaces as a retryable timeout instead of a silent end. +test("stall watchdog aborts a silent mid-stream", async () => { + const server = await listen((req, res) => { + res.writeHead(200, { "content-type": "text/event-stream" }); + res.write("data: one\n\n"); + // then go silent forever + }); + try { + const port = server.address().port; + const resp = await fetchWithTimeout(`http://127.0.0.1:${port}`, {}, { ttfbMs: 500, stallMs: 100 }); + const reader = resp.body.getReader(); + await reader.read(); // first chunk arrives + await assert.rejects(reader.read(), (err) => err.code === "stream_total_timeout"); + } finally { + await close(server); + } +});